Merge pull request #1501 from charleszqwang/logging

Converting From Log15 to ZeroLog

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")
 	}
 }
 

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()

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
 }
 

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

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

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)

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)

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
 }

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 {

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)
 	}

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
 }

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
 	}

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")
 	}
 }