From 355b43eacf490bdfde5b2dd500decd152532cd96 Mon Sep 17 00:00:00 2001 From: charleszqwang Date: Wed, 28 Aug 2019 10:18:00 -0700 Subject: [PATCH] Zerologging --- cmd/client/txgen/main.go | 59 +++++++++++++++++++++++------- cmd/harmony/main.go | 33 ++++++++++------- core/rawdb/accessors_chain.go | 4 +- internal/attack/attack.go | 12 ++++-- internal/genesis/genesis.go | 2 +- internal/hmyapi/blockchain.go | 9 ++++- internal/hmyapi/private_account.go | 7 +++- internal/hmyapi/util.go | 10 ++++- internal/memprofiling/lib.go | 17 +++++---- internal/profiler/profiler.go | 16 +++++++- internal/shardchain/shardchains.go | 21 ++++++++--- internal/utils/utils.go | 18 ++++++--- node/node.go | 2 +- 13 files changed, 152 insertions(+), 58 deletions(-) diff --git a/cmd/client/txgen/main.go b/cmd/client/txgen/main.go index 14ef4084d..7d84a9ee8 100644 --- a/cmd/client/txgen/main.go +++ b/cmd/client/txgen/main.go @@ -151,7 +151,9 @@ func main() { MaxNumTxsPerBatch: *numTxns, } shardID := *shardIDFlag - utils.GetLogInstance().Debug("Cross Shard Ratio Is Set But not used", "cx ratio", *crossShardRatio) + utils.Logger().Debug(). + Int("cx ratio", *crossShardRatio). + Msg("Cross Shard Ratio Is Set But not used") // TODO(Richard): refactor this chuck to a single method // Setup a logger to stdout and log file. @@ -166,20 +168,30 @@ func main() { txGen.RunServices() start := time.Now() totalTime := float64(*duration) - utils.GetLogInstance().Debug("Total Duration", "totalTime", totalTime, "RunForever", isDurationForever(totalTime)) + utils.Logger().Debug(). + Float64("totalTime", totalTime). + Bool("RunForever", isDurationForever(totalTime)). + Msg("Total Duration") ticker := time.NewTicker(checkFrequency * time.Second) txGen.DoSyncWithoutConsensus() syncLoop: for { t := time.Now() if totalTime > 0 && t.Sub(start).Seconds() >= totalTime { - utils.GetLogInstance().Debug("Generator timer ended in syncLoop.", "duration", (int(t.Sub(start))), "startTime", start, "totalTime", totalTime) + utils.Logger().Debug(). + Int("duration", (int(t.Sub(start)))). + Time("startTime", start). + Float64("totalTime", totalTime). + Msg("Generator timer ended in syncLoop.") break syncLoop } select { case <-ticker.C: if txGen.State.String() == "NodeReadyForConsensus" { - utils.GetLogInstance().Debug("Generator is now in Sync.", "txgen node", txGen.SelfPeer, "Node State", txGen.State.String()) + utils.Logger().Debug(). + Str("txgen node", txGen.SelfPeer.String()). + Str("Node State", txGen.State.String()). + Msg("Generator is now in Sync.") ticker.Stop() break syncLoop } @@ -188,14 +200,24 @@ syncLoop: readySignal := make(chan uint32) // This func is used to update the client's blockchain when new blocks are received from the leaders updateBlocksFunc := func(blocks []*types.Block) { - utils.GetLogInstance().Info("[Txgen] Received new block", "block num", blocks[0].NumberU64()) + utils.Logger().Info(). + Uint64("block num", blocks[0].NumberU64()). + Msg("[Txgen] Received new block") for _, block := range blocks { shardID := block.ShardID() if txGen.Consensus.ShardID == shardID { - utils.GetLogInstance().Info("Got block from leader", "txNum", len(block.Transactions()), "shardID", shardID, "preHash", block.ParentHash().Hex(), "currentBlock", txGen.Blockchain().CurrentBlock().NumberU64(), "incoming block", block.NumberU64()) + utils.Logger().Info(). + Int("txNum", len(block.Transactions())). + Uint32("shardID", shardID). + Str("preHash", block.ParentHash().Hex()). + Uint64("currentBlock", txGen.Blockchain().CurrentBlock().NumberU64()). + Uint64("incoming block", block.NumberU64()). + Msg("Got block from leader") if block.NumberU64()-txGen.Blockchain().CurrentBlock().NumberU64() == 1 { if err := txGen.AddNewBlock(block); err != nil { - utils.GetLogInstance().Error("Error when adding new block", "error", err) + utils.Logger().Error(). + Err(err). + Msg("Error when adding new block") } stateMutex.Lock() if err := txGen.Worker.UpdateCurrent(block.Coinbase()); err != nil { @@ -221,9 +243,16 @@ syncLoop: pushLoop: for { t := time.Now() - utils.GetLogInstance().Debug("Current running time", "running time", t.Sub(start).Seconds(), "totaltime", totalTime) + utils.Logger().Debug(). + Float64("running time", t.Sub(start).Seconds()). + Float64("totalTime", totalTime). + Msg("Current running time") if !isDurationForever(totalTime) && t.Sub(start).Seconds() >= totalTime { - utils.GetLogInstance().Debug("Generator timer ended.", "duration", (int(t.Sub(start))), "startTime", start, "totalTime", totalTime) + utils.Logger().Debug(). + Int("duration", (int(t.Sub(start)))). + Time("startTime", start). + Float64("totalTime", totalTime). + Msg("Generator timer ended.") break pushLoop } if shardID != 0 { @@ -231,7 +260,7 @@ pushLoop: if otherHeight >= 1 { go func() { readySignal <- uint32(shardID) - utils.GetLogInstance().Debug("Same blockchain height so readySignal generated") + utils.Logger().Debug().Msg("Same blockchain height so readySignal generated") time.Sleep(3 * time.Second) // wait for nodes to be ready }() } @@ -242,13 +271,15 @@ pushLoop: lock := sync.Mutex{} txs, err := GenerateSimulatedTransactionsAccount(uint32(shardID), txGen, setting) if err != nil { - utils.GetLogInstance().Debug("Error in Generating Txns", "Err", err) + utils.Logger().Debug(). + Err(err). + Msg("Error in Generating Txns") } lock.Lock() SendTxsToShard(txGen, txs, uint32(shardID)) lock.Unlock() case <-time.After(10 * time.Second): - utils.GetLogInstance().Warn("No new block is received so far") + utils.Logger().Warn().Msg("No new block is received so far") } } } @@ -264,7 +295,9 @@ func SendTxsToShard(clientNode *node.Node, txs types.Transactions, shardID uint3 err = clientNode.GetHost().SendMessageToGroups([]p2p.GroupID{clientGroup}, p2p_host.ConstructP2pMessage(byte(0), msg)) } if err != nil { - utils.GetLogInstance().Debug("Error in Sending Txns", "Err", err) + utils.Logger().Debug(). + Err(err). + Msg("Error in Sending Txns") } } diff --git a/cmd/harmony/main.go b/cmd/harmony/main.go index 5a5884351..a6db0afe0 100644 --- a/cmd/harmony/main.go +++ b/cmd/harmony/main.go @@ -304,8 +304,9 @@ func setupConsensusAndNode(nodeConfig *nodeconfig.ConfigType) *node.Node { } // TODO: add staking support // currentNode.StakingAccount = myAccount - utils.GetLogInstance().Info("node account set", - "address", common.MustAddressToBech32(currentNode.StakingAccount.Address)) + utils.Logger().Info(). + Str("address", common.MustAddressToBech32(currentNode.StakingAccount.Address)). + Msg("node account set") // TODO: refactor the creation of blockchain out of node.New() currentConsensus.ChainReader = currentNode.Blockchain() @@ -353,7 +354,9 @@ func setupConsensusAndNode(nodeConfig *nodeconfig.ConfigType) *node.Node { height := currentNode.Blockchain().CurrentBlock().NumberU64() currentConsensus.SetViewID(height) - utils.GetLogInstance().Info("Init Blockchain", "height", height) + utils.Logger().Info(). + Uint64("height", height). + Msg("Init Blockchain") // Assign closure functions to the consensus object currentConsensus.BlockVerifier = currentNode.VerifyNewBlock @@ -415,7 +418,10 @@ func main() { } if *shardID >= 0 { - utils.GetLogInstance().Info("ShardID Override", "original", initialAccount.ShardID, "override", *shardID) + utils.Logger().Info(). + Uint32("original", initialAccount.ShardID). + Int("override", *shardID). + Msg("ShardID Override") initialAccount.ShardID = uint32(*shardID) } @@ -430,15 +436,16 @@ func main() { if *isExplorer { startMsg = "==== New Explorer Node ====" } - utils.GetLogInstance().Info(startMsg, - "BlsPubKey", hex.EncodeToString(nodeConfig.ConsensusPubKey.Serialize()), - "ShardID", nodeConfig.ShardID, - "ShardGroupID", nodeConfig.GetShardGroupID(), - "BeaconGroupID", nodeConfig.GetBeaconGroupID(), - "ClientGroupID", nodeConfig.GetClientGroupID(), - "Role", currentNode.NodeConfig.Role(), - "multiaddress", fmt.Sprintf("/ip4/%s/tcp/%s/p2p/%s", - *ip, *port, nodeConfig.Host.GetID().Pretty())) + + utils.Logger().Info(). + Str("BlsPubKey", hex.EncodeToString(nodeConfig.ConsensusPubKey.Serialize())). + Uint32("ShardID", nodeConfig.ShardID). + Str("ShardGroupID", nodeConfig.GetShardGroupID().String()). + Str("BeaconGroupID", nodeConfig.GetBeaconGroupID().String()). + Str("ClientGroupID", nodeConfig.GetClientGroupID().String()). + Str("Role", currentNode.NodeConfig.Role().String()). + Str("multiaddress", fmt.Sprintf("/ip4/%s/tcp/%s/p2p/%s", *ip, *port, nodeConfig.Host.GetID().Pretty())). + Msg(startMsg) if *enableMemProfiling { memprofiling.GetMemProfiling().Start() diff --git a/core/rawdb/accessors_chain.go b/core/rawdb/accessors_chain.go index 07037720e..878903808 100644 --- a/core/rawdb/accessors_chain.go +++ b/core/rawdb/accessors_chain.go @@ -464,7 +464,9 @@ func WriteLastCommits( if err = db.Put(lastCommitsKey, data); err != nil { return ctxerror.New("cannot write last commits").WithCause(err) } - utils.GetLogger().Info("wrote last commits", "numShards", len(data)) + utils.Logger().Info(). + Int("numShards", len(data)). + Msg("wrote last commits") return nil } diff --git a/internal/attack/attack.go b/internal/attack/attack.go index e4abdba20..230123eab 100644 --- a/internal/attack/attack.go +++ b/internal/attack/attack.go @@ -76,7 +76,9 @@ func (attack *Model) NodeKilledByItSelf() { } if rand.Intn(HitRate) == 0 { - utils.GetLogInstance().Debug("******************Killing myself******************", "PID: ", os.Getpid()) + utils.Logger().Debug(). + Int("PID", os.Getpid()). + Msg("******************Killing myself******************") os.Exit(1) } } @@ -87,7 +89,9 @@ func (attack *Model) DelayResponse() { return } if rand.Intn(HitRate) == 0 { - utils.GetLogInstance().Debug("******************Model: DelayResponse******************", "PID: ", os.Getpid()) + utils.Logger().Debug(). + Int("PID", os.Getpid()). + Msg("******************Model: DelayResponse******************") time.Sleep(DelayResponseDuration) } } @@ -98,7 +102,9 @@ func (attack *Model) IncorrectResponse() bool { return false } if rand.Intn(HitRate) == 0 { - utils.GetLogInstance().Debug("******************Model: IncorrectResponse******************", "PID: ", os.Getpid()) + utils.Logger().Debug(). + Int("PID", os.Getpid()). + Msg("******************Model: IncorrectResponse******************") return true } return false diff --git a/internal/genesis/genesis.go b/internal/genesis/genesis.go index e8d7c96f4..5f8c9e889 100644 --- a/internal/genesis/genesis.go +++ b/internal/genesis/genesis.go @@ -28,7 +28,7 @@ func (d DeployAccount) String() string { func BeaconAccountPriKey() *ecdsa.PrivateKey { prikey, err := ecdsa.GenerateKey(crypto.S256(), strings.NewReader(genesisString)) if err != nil && prikey == nil { - utils.GetLogInstance().Error("Failed to generate beacon chain contract deployer account") + utils.Logger().Error().Msg("Failed to generate beacon chain contract deployer account") os.Exit(111) } return prikey diff --git a/internal/hmyapi/blockchain.go b/internal/hmyapi/blockchain.go index 7423b662d..344f4dded 100644 --- a/internal/hmyapi/blockchain.go +++ b/internal/hmyapi/blockchain.go @@ -108,7 +108,9 @@ func (s *PublicBlockChainAPI) Call(ctx context.Context, args CallArgs, blockNr r func doCall(ctx context.Context, b Backend, args CallArgs, blockNr rpc.BlockNumber, vmCfg vm.Config, timeout time.Duration, globalGasCap *big.Int) ([]byte, uint64, bool, error) { defer func(start time.Time) { - utils.GetLogInstance().Debug("Executing EVM call finished", "runtime", time.Since(start)) + utils.Logger().Debug(). + Dur("runtime", time.Since(start)). + Msg("Executing EVM call finished") }(time.Now()) state, header, err := b.StateAndHeaderByNumber(ctx, blockNr) @@ -139,7 +141,10 @@ func doCall(ctx context.Context, b Backend, args CallArgs, blockNr rpc.BlockNumb gas = uint64(*args.Gas) } if globalGasCap != nil && globalGasCap.Uint64() < gas { - utils.GetLogInstance().Warn("Caller gas above allowance, capping", "requested", gas, "cap", globalGasCap) + utils.Logger().Warn(). + Uint64("requested", gas). + Uint64("cap", globalGasCap.Uint64()). + Msg("Caller gas above allowance, capping") gas = globalGasCap.Uint64() } gasPrice := new(big.Int).SetUint64(defaultGasPrice) diff --git a/internal/hmyapi/private_account.go b/internal/hmyapi/private_account.go index 2ebe5c18f..e59c15714 100644 --- a/internal/hmyapi/private_account.go +++ b/internal/hmyapi/private_account.go @@ -38,7 +38,12 @@ func (s *PrivateAccountAPI) SendTransaction(ctx context.Context, args SendTxArgs } signed, err := s.signTransaction(ctx, &args, passwd) if err != nil { - utils.GetLogger().Warn("Failed transaction send attempt", "from", args.From, "to", args.To, "value", args.Value.ToInt(), "err", err) + utils.Logger().Warn(). + Str("from", args.From.Hex()). + Str("to", args.To.Hex()). + Uint64("value", args.Value.ToInt().Uint64()). + AnErr("err", err). + Msg("Failed transaction send attempt") return common.Hash{}, err } return SubmitTransaction(ctx, s.b, signed) diff --git a/internal/hmyapi/util.go b/internal/hmyapi/util.go index 68466ecf3..3462a6bc9 100644 --- a/internal/hmyapi/util.go +++ b/internal/hmyapi/util.go @@ -23,9 +23,15 @@ func SubmitTransaction(ctx context.Context, b Backend, tx *types.Transaction) (c return common.Hash{}, err } addr := crypto.CreateAddress(from, tx.Nonce()) - utils.GetLogger().Info("Submitted contract creation", "fullhash", tx.Hash().Hex(), "contract", common2.MustAddressToBech32(addr)) + utils.Logger().Info(). + Str("fullhash", tx.Hash().Hex()). + Str("contract", common2.MustAddressToBech32(addr)). + Msg("Submitted contract creation") } else { - utils.GetLogger().Info("Submitted transaction", "fullhash", tx.Hash().Hex(), "recipient", tx.To()) + utils.Logger().Info(). + Str("fullhash", tx.Hash().Hex()). + Str("recipient", tx.To().Hex()). + Msg("Submitted transaction") } return tx.Hash(), nil } diff --git a/internal/memprofiling/lib.go b/internal/memprofiling/lib.go index 926ea0b1a..6820b86a6 100644 --- a/internal/memprofiling/lib.go +++ b/internal/memprofiling/lib.go @@ -47,7 +47,9 @@ func (m *MemProfiling) Config() { Addr: fmt.Sprintf("%s:%s", nodeconfig.GetDefaultConfig().IP, utils.GetPortFromDiff(nodeconfig.GetDefaultConfig().Port, MemProfilingPortDiff)), Handler: m.h, } - utils.GetLogInstance().Info("running mem profiling", "port", utils.GetPortFromDiff(nodeconfig.GetDefaultConfig().Port, MemProfilingPortDiff)) + utils.Logger().Info(). + Str("port", utils.GetPortFromDiff(nodeconfig.GetDefaultConfig().Port, MemProfilingPortDiff)). + Msgf("running mem profiling") } // Add adds variables to watch for profiling. @@ -67,7 +69,6 @@ func (m *MemProfiling) Add(name string, v interface{}) { func (m *MemProfiling) Start() { go m.s.ListenAndServe() m.PeriodicallyScanMemSize() - utils.GetLogInstance().Info("Start memprofiling.") } // Stop stops mem profiling. @@ -86,7 +87,7 @@ func (m *MemProfiling) PeriodicallyScanMemSize() { for k, v := range m.observedObject { s := memsize.Scan(v) r := s.Report() - utils.GetLogInstance().Info(fmt.Sprintf("memsize report for %s:\n %s", k, r)) + utils.Logger().Info().Msgf("memsize report for %s:\n %s", k, r) } m.mu.Unlock() } @@ -120,11 +121,11 @@ func MaybeCallGCPeriodically() { func PrintMemUsage(msg string) { var m runtime.MemStats runtime.ReadMemStats(&m) - utils.GetLogInstance().Info(msg, - "alloc", bToMb(m.Alloc), - "totalalloc", bToMb(m.TotalAlloc), - "sys", bToMb(m.Sys), - "numgc", m.NumGC) + utils.Logger().Info(). + Uint64("alloc", bToMb(m.Alloc)). + Uint64("totalalloc", bToMb(m.TotalAlloc)). + Uint64("sys", bToMb(m.Sys)). + Uint32("numgc", m.NumGC) } func bToMb(b uint64) uint64 { diff --git a/internal/profiler/profiler.go b/internal/profiler/profiler.go index d477dd064..5f76a4123 100644 --- a/internal/profiler/profiler.go +++ b/internal/profiler/profiler.go @@ -46,7 +46,15 @@ func (profiler *Profiler) LogMemory() { // log mem usage info, _ := profiler.proc.MemoryInfo() memMap, _ := profiler.proc.MemoryMaps(false) - utils.GetLogInstance().Info("Mem Report", "info", info, "map", memMap, "shardID", profiler.shardID) + loggedMemMap := "" + for _, mems := range *memMap { + loggedMemMap += mems.String() + "; " + } + utils.Logger().Info(). + Str("info", info.String()). + Str("map", loggedMemMap). + Uint32("shardID", profiler.shardID). + Msg("Mem Report") time.Sleep(3 * time.Second) } @@ -58,7 +66,11 @@ func (profiler *Profiler) LogCPU() { // log cpu usage percent, _ := profiler.proc.CPUPercent() times, _ := profiler.proc.Times() - utils.GetLogInstance().Info("CPU Report", "percent", percent, "times", times, "shardID", profiler.shardID) + utils.Logger().Info(). + Float64("percent", percent). + Str("times", times.String()). + Uint32("shardID", profiler.shardID). + Msg("CPU Report") time.Sleep(3 * time.Second) } diff --git a/internal/shardchain/shardchains.go b/internal/shardchain/shardchains.go index 642b9b6b9..2e3942372 100644 --- a/internal/shardchain/shardchains.go +++ b/internal/shardchain/shardchains.go @@ -81,8 +81,9 @@ func (sc *CollectionImpl) ShardChain(shardID uint32, networkType nodeconfig.Netw return nil, ctxerror.New("cannot open chain database").WithCause(err) } if rawdb.ReadCanonicalHash(db, 0) == (common.Hash{}) { - utils.GetLogger().Info("initializing a new chain database", - "shardID", shardID) + utils.Logger().Info(). + Uint32("shardID", shardID). + Msg("initializing a new chain database") if err := sc.dbInit.InitChainDB(db, shardID); err != nil { return nil, ctxerror.New("cannot initialize a new chain database"). WithCause(err) @@ -129,11 +130,15 @@ func (sc *CollectionImpl) CloseShardChain(shardID uint32) error { if !ok { return ctxerror.New("shard chain not found", "shardID", shardID) } - utils.GetLogger().Info("closing shard chain", "shardID", shardID) + utils.Logger().Info(). + Uint32("shardID", shardID). + Msg("closing shard chain") delete(sc.pool, shardID) bc.Stop() bc.ChainDb().Close() - utils.GetLogger().Info("closed shard chain", "shardID", shardID) + utils.Logger().Info(). + Uint32("shardID", shardID). + Msg("closed shard chain") return nil } @@ -145,10 +150,14 @@ func (sc *CollectionImpl) Close() error { sc.pool = newPool sc.mtx.Unlock() for shardID, bc := range oldPool { - utils.GetLogger().Info("closing shard chain", "shardID", shardID) + utils.Logger().Info(). + Uint32("shardID", shardID). + Msg("closing shard chain") bc.Stop() bc.ChainDb().Close() - utils.GetLogger().Info("closed shard chain", "shardID", shardID) + utils.Logger().Info(). + Uint32("shardID", shardID). + Msg("closed shard chain") } return nil } diff --git a/internal/utils/utils.go b/internal/utils/utils.go index 57224beab..7c4530971 100644 --- a/internal/utils/utils.go +++ b/internal/utils/utils.go @@ -63,7 +63,9 @@ func ConvertFixedDataIntoByteArray(data interface{}) []byte { buff := new(bytes.Buffer) err := binary.Write(buff, binary.BigEndian, data) if err != nil { - GetLogger().Crit("Failed to convert fixed data into byte array", "err", err) + Logger().Error(). + AnErr("err", err). + Msg("Failed to convert fixed data into byte array") } return buff.Bytes() } @@ -195,16 +197,22 @@ func LoadKeyFromFile(keyfile string) (key p2p_crypto.PrivKey, pk p2p_crypto.PubK var keyStruct PrivKeyStore err = Load(keyfile, &keyStruct) if err != nil { - GetLogger().Info("No priviate key can be loaded from file", "keyfile", keyfile) - GetLogger().Info("Using random private key") + Logger().Info(). + Str("keyfile", keyfile). + Msg("No private key can be loaded from file") + Logger().Info().Msg("Using random private key") key, pk, err = GenKeyP2PRand() if err != nil { - GetLogger().Crit("LoadKeyFromFile", "GenKeyP2PRand Error", err) + Logger().Error(). + AnErr("GenKeyP2PRand Error", err). + Msg("LoadedKeyFromFile") panic(err) } err = SaveKeyToFile(keyfile, key) if err != nil { - GetLogger().Error("failed to save key to keyfile", "keyfile", err) + Logger().Error(). + AnErr("keyfile", err). + Msg("failed to save key to keyfile") } return key, pk, nil } diff --git a/node/node.go b/node/node.go index 021ba5ada..f0458b5f4 100644 --- a/node/node.go +++ b/node/node.go @@ -237,7 +237,7 @@ func (node *Node) reducePendingTransactions() { // If length of pendingTransactions is greater than TxPoolLimit then by greedy take the TxPoolLimit recent transactions. if curLen > txPoolLimit+txPoolLimit { node.pendingTransactions = append(types.Transactions(nil), node.pendingTransactions[curLen-txPoolLimit:]...) - utils.GetLogger().Info("mem stat reduce pending transaction") + utils.Logger().Info().Msg("mem stat reduce pending transaction") } }