Merge pull request #1785 from flicker-harmony/pr_log_rotation

Replace ethereum log with zerolog to resolve logging rotation issue
pull/1822/head
flicker-harmony 5 years ago committed by GitHub
commit 621e8bd35c
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
  1. 7
      accounts/abi/bind/util.go
  2. 19
      accounts/keystore/account_cache.go
  3. 8
      accounts/keystore/file_cache.go
  4. 6
      api/service/explorer/service.go
  5. 3
      api/service/explorer/storage.go
  6. 4
      cmd/client/txgen/main.go
  7. 15
      cmd/harmony/main.go
  8. 6
      consensus/consensus_v2.go
  9. 6
      contracts/contract_caller.go
  10. 15
      node/node.go
  11. 23
      node/node_handler.go
  12. 13
      node/node_newblock.go
  13. 19
      node/node_resharding.go
  14. 5
      node/node_syncing.go

@ -32,17 +32,16 @@ import (
func WaitMined(ctx context.Context, b DeployBackend, tx *types.Transaction) (*types.Receipt, error) {
queryTicker := time.NewTicker(time.Second)
defer queryTicker.Stop()
logger := utils.GetLogInstance().New("hash", tx.Hash())
utils.Logger().Info().Str("hash", tx.Hash().Hex())
for {
receipt, err := b.TransactionReceipt(ctx, tx.Hash())
if receipt != nil {
return receipt, nil
}
if err != nil {
logger.Trace("Receipt retrieval failed", "err", err)
utils.Logger().Debug().Err(err).Msg("Receipt retrieval failed")
} else {
logger.Trace("Transaction not yet mined")
utils.Logger().Debug().Msg("Transaction not yet mined")
}
// Wait for the next round.
select {

@ -236,7 +236,7 @@ func (ac *accountCache) scanAccounts() error {
// Scan the entire folder metadata for file changes
creates, deletes, updates, err := ac.fileC.scan(ac.keydir)
if err != nil {
utils.GetLogger().Debug("Failed to reload keystore contents", "err", err)
utils.Logger().Debug().Err(err).Msg("Failed to reload keystore contents")
return err
}
if creates.Cardinality() == 0 && deletes.Cardinality() == 0 && updates.Cardinality() == 0 {
@ -252,7 +252,10 @@ func (ac *accountCache) scanAccounts() error {
readAccount := func(path string) *accounts.Account {
fd, err := os.Open(path)
if err != nil {
utils.GetLogger().Trace("Failed to open keystore file", "path", path, "err", err)
utils.Logger().Debug().
Str("path", path).
Err(err).
Msg("Failed to open keystore file")
return nil
}
defer fd.Close()
@ -263,9 +266,15 @@ func (ac *accountCache) scanAccounts() error {
addr := common2.ParseAddr(key.Address)
switch {
case err != nil:
utils.GetLogger().Debug("Failed to decode keystore key", "path", path, "err", err)
utils.Logger().Debug().
Str("path", path).
Err(err).
Msg("Failed to decode keystore key")
case (addr == common.Address{}):
utils.GetLogger().Debug("Failed to decode keystore key", "path", path, "err", "missing or zero address")
utils.Logger().Debug().
Str("path", path).
Err(err).
Msg("Failed to decode keystore key, missing or zero address")
default:
return &accounts.Account{
Address: addr,
@ -298,6 +307,6 @@ func (ac *accountCache) scanAccounts() error {
case ac.notify <- struct{}{}:
default:
}
utils.GetLogger().Trace("Handled keystore changes", "time", end.Sub(start))
utils.Logger().Debug().Uint64("time", uint64(end.Sub(start))).Msg("Handled keystore changes")
return nil
}

@ -60,7 +60,7 @@ func (fc *fileCache) scan(keyDir string) (mapset.Set, mapset.Set, mapset.Set, er
path := filepath.Join(keyDir, fi.Name())
// Skip any non-key files from the folder
if nonKeyFile(fi) {
utils.GetLogger().Trace("Ignoring file on account scan", "path", path)
utils.Logger().Debug().Str("path", path).Msg("Ignoring file on account scan")
continue
}
// Gather the set of all and fresly modified files
@ -85,7 +85,11 @@ func (fc *fileCache) scan(keyDir string) (mapset.Set, mapset.Set, mapset.Set, er
t3 := time.Now()
// Report on the scanning stats and return
utils.GetLogger().Debug("FS scan times", "list", t1.Sub(t0), "set", t2.Sub(t1), "diff", t3.Sub(t2))
utils.Logger().Debug().
Uint64("list", uint64(t1.Sub(t0))).
Uint64("set", uint64(t2.Sub(t1))).
Uint64("diff", uint64(t3.Sub(t2))).
Msg("FS scan times")
return creates, deletes, updates, nil
}

@ -25,7 +25,6 @@ import (
bls2 "github.com/harmony-one/harmony/crypto/bls"
"github.com/harmony-one/harmony/internal/bech32"
common2 "github.com/harmony-one/harmony/internal/common"
"github.com/harmony-one/harmony/internal/ctxerror"
"github.com/harmony-one/harmony/internal/utils"
"github.com/harmony-one/harmony/p2p"
"github.com/harmony-one/harmony/shard"
@ -669,7 +668,7 @@ func (s *Service) GetExplorerAddress(w http.ResponseWriter, r *http.Request) {
parsedAddr := common2.ParseAddr(id)
oneAddr, err := common2.AddressToBech32(parsedAddr)
if err != nil {
utils.Logger().Warn().Msg("unrecognized address format")
utils.Logger().Warn().Err(err).Msg("unrecognized address format")
w.WriteHeader(http.StatusBadRequest)
return
}
@ -688,8 +687,7 @@ func (s *Service) GetExplorerAddress(w http.ResponseWriter, r *http.Request) {
data := &Data{}
defer func() {
if err := json.NewEncoder(w).Encode(data.Address); err != nil {
ctxerror.Warn(utils.WithCallerSkip(utils.GetLogInstance(), 1), err,
"cannot JSON-encode Address")
utils.Logger().Warn().Err(err).Msg("cannot JSON-encode Address")
}
}()
if id == "" {

@ -10,7 +10,6 @@ import (
"github.com/ethereum/go-ethereum/rlp"
"github.com/harmony-one/harmony/core/types"
"github.com/harmony-one/harmony/internal/ctxerror"
"github.com/harmony-one/harmony/internal/utils"
"github.com/harmony-one/harmony/shard"
)
@ -117,7 +116,7 @@ func (storage *Storage) Dump(block *types.Block, height uint64) {
storage.UpdateAddress(batch, explorerTransaction, tx)
}
if err := batch.Write(); err != nil {
ctxerror.Warn(utils.GetLogger(), err, "cannot write batch")
utils.Logger().Warn().Err(err).Msg("cannot write batch")
}
}

@ -22,7 +22,6 @@ import (
"github.com/harmony-one/harmony/core/types"
"github.com/harmony-one/harmony/crypto/bls"
nodeconfig "github.com/harmony-one/harmony/internal/configs/node"
"github.com/harmony-one/harmony/internal/ctxerror"
"github.com/harmony-one/harmony/internal/genesis"
"github.com/harmony-one/harmony/internal/params"
"github.com/harmony-one/harmony/internal/shardchain"
@ -221,8 +220,7 @@ syncLoop:
}
stateMutex.Lock()
if err := txGen.Worker.UpdateCurrent(block.Coinbase()); err != nil {
ctxerror.Warn(utils.GetLogger(), err,
"(*Worker).UpdateCurrent failed")
utils.Logger().Warn().Err(err).Msg("(*Worker).UpdateCurrent failed")
}
stateMutex.Unlock()
readySignal <- shardID

@ -24,7 +24,6 @@ import (
"github.com/harmony-one/harmony/internal/common"
nodeconfig "github.com/harmony-one/harmony/internal/configs/node"
shardingconfig "github.com/harmony-one/harmony/internal/configs/sharding"
"github.com/harmony-one/harmony/internal/ctxerror"
"github.com/harmony-one/harmony/internal/genesis"
hmykey "github.com/harmony-one/harmony/internal/keystore"
"github.com/harmony-one/harmony/internal/memprofiling"
@ -269,7 +268,7 @@ func createGlobalConfig() *nodeconfig.ConfigType {
myHost, err = p2pimpl.NewHost(&selfPeer, nodeConfig.P2pPriKey)
if *logConn && nodeConfig.GetNetworkType() != nodeconfig.Mainnet {
myHost.GetP2PHost().Network().Notify(utils.NewConnLogger(utils.GetLogInstance()))
myHost.GetP2PHost().Network().Notify(utils.NewConnLogger(utils.GetLogger()))
}
if err != nil {
panic("unable to new host in harmony")
@ -374,8 +373,10 @@ func setupConsensusAndNode(nodeConfig *nodeconfig.ConfigType) *node.Node {
// This needs to be executed after consensus and drand are setup
if err := currentNode.InitConsensusWithValidators(); err != nil {
ctxerror.Crit(utils.GetLogger(), err, "InitConsensusWithMembers failed",
"shardID", *shardID)
utils.Logger().Warn().
Int("shardID", *shardID).
Err(err).
Msg("InitConsensusWithMembers failed")
}
// Set the consensus ID to be the current block number
@ -469,7 +470,7 @@ func main() {
currentNode.SetBeaconSyncFreq(*beaconSyncFreq)
if nodeConfig.ShardID != shard.BeaconChainShardID && currentNode.NodeConfig.Role() != nodeconfig.ExplorerNode {
utils.GetLogInstance().Info("SupportBeaconSyncing", "shardID", currentNode.Blockchain().ShardID(), "shardID", nodeConfig.ShardID)
utils.Logger().Info().Uint32("shardID", currentNode.Blockchain().ShardID()).Uint32("shardID", nodeConfig.ShardID).Msg("SupportBeaconSyncing")
go currentNode.SupportBeaconSyncing()
}
@ -497,7 +498,9 @@ func main() {
currentNode.RunServices()
// RPC for SDK not supported for mainnet.
if err := currentNode.StartRPC(*port); err != nil {
ctxerror.Warn(utils.GetLogger(), err, "StartRPC failed")
utils.Logger().Warn().
Err(err).
Msg("StartRPC failed")
}
// Run additional node collectors

@ -834,9 +834,6 @@ func (consensus *Consensus) finalizeCommits() {
Str("blockHash", block.Hash().String()).
Int("index", consensus.Decider.IndexOf(consensus.PubKey)).
Msg("HOORAY!!!!!!! CONSENSUS REACHED!!!!!!!")
// Print to normal log too
utils.GetLogInstance().Info("HOORAY!!!!!!! CONSENSUS REACHED!!!!!!!", "BlockNum", block.NumberU64())
// Send signal to Node so the new block can be added and new round of consensus can be triggered
consensus.ReadySignal <- struct{}{}
}
@ -967,6 +964,9 @@ func (consensus *Consensus) LastCommitSig() ([]byte, []byte, error) {
if err != nil || len(lastCommits) < 96 {
msgs := consensus.FBFTLog.GetMessagesByTypeSeq(msg_pb.MessageType_COMMITTED, consensus.blockNum-1)
if len(msgs) != 1 {
utils.Logger().Error().
Int("numCommittedMsg", len(msgs)).
Msg("GetLastCommitSig failed with wrong number of committed message")
return nil, nil, ctxerror.New("GetLastCommitSig failed with wrong number of committed message", "numCommittedMsg", len(msgs))
}
lastCommits = msgs[0].Payload

@ -35,7 +35,7 @@ func (cc *ContractCaller) CallContract(tx *types.Transaction) ([]byte, error) {
currBlock := cc.blockchain.CurrentBlock()
msg, err := tx.AsMessage(types.MakeSigner(cc.config, currBlock.Header().Epoch()))
if err != nil {
utils.GetLogInstance().Error("[ABI] Failed to convert transaction to message", "error", err)
utils.Logger().Error().Err(err).Msg("[ABI] Failed to convert transaction to message")
return []byte{}, err
}
evmContext := core.NewEVMContext(msg, currBlock.Header(), cc.blockchain, nil)
@ -43,7 +43,7 @@ func (cc *ContractCaller) CallContract(tx *types.Transaction) ([]byte, error) {
// about the transaction and calling mechanisms.
stateDB, err := cc.blockchain.State()
if err != nil {
utils.GetLogInstance().Error("[ABI] Failed to retrieve state db", "error", err)
utils.Logger().Error().Err(err).Msg("[ABI] Failed to retrieve state db")
return []byte{}, err
}
vmenv := vm.NewEVM(evmContext, stateDB, cc.config, vm.Config{})
@ -51,7 +51,7 @@ func (cc *ContractCaller) CallContract(tx *types.Transaction) ([]byte, error) {
returnValue, _, failed, err := core.NewStateTransition(vmenv, msg, gaspool).TransitionDb()
if err != nil || failed {
utils.GetLogInstance().Error("[ABI] Failed executing the transaction", "error", err)
utils.Logger().Error().Err(err).Msg("[ABI] Failed executing the transaction")
return []byte{}, err
}
return returnValue, nil

@ -244,9 +244,10 @@ func (node *Node) Blockchain() *core.BlockChain {
shardID := node.NodeConfig.ShardID
bc, err := node.shardChains.ShardChain(shardID)
if err != nil {
err = ctxerror.New("cannot get shard chain", "shardID", shardID).
WithCause(err)
ctxerror.Log15(utils.GetLogger().Crit, err)
utils.Logger().Error().
Uint32("shardID", shardID).
Err(err).
Msg("cannot get shard chain")
}
return bc
}
@ -255,8 +256,7 @@ func (node *Node) Blockchain() *core.BlockChain {
func (node *Node) Beaconchain() *core.BlockChain {
bc, err := node.shardChains.ShardChain(0)
if err != nil {
err = ctxerror.New("cannot get beaconchain").WithCause(err)
ctxerror.Log15(utils.GetLogger().Crit, err)
utils.Logger().Error().Err(err).Msg("cannot get beaconchain")
}
return bc
}
@ -557,6 +557,7 @@ func New(host p2p.Host, consensusObj *consensus.Consensus, chainDBFactory shardc
// keys for consensus and drand
func (node *Node) InitConsensusWithValidators() (err error) {
if node.Consensus == nil {
utils.Logger().Error().Msg("[InitConsensusWithValidators] consenus is nil; Cannot figure out shardID")
return ctxerror.New("[InitConsensusWithValidators] consenus is nil; Cannot figure out shardID")
}
shardID := node.Consensus.ShardID
@ -572,6 +573,10 @@ func (node *Node) InitConsensusWithValidators() (err error) {
epoch, node.Consensus.ChainReader, int(shardID),
)
if len(pubKeys) == 0 {
utils.Logger().Error().
Uint32("shardID", shardID).
Uint64("blockNum", blockNum).
Msg("[InitConsensusWithValidators] PublicKeys is Empty, Cannot update public keys")
return ctxerror.New(
"[InitConsensusWithValidators] PublicKeys is Empty, Cannot update public keys",
"shardID", shardID,

@ -158,7 +158,7 @@ func (node *Node) HandleMessage(content []byte, sender libp2p_peer.ID) {
node.pingMessageHandler(msgPayload, sender)
case proto_node.ShardState:
if err := node.epochShardStateMessageHandler(msgPayload); err != nil {
ctxerror.Log15(utils.GetLogger().Warn, err)
utils.Logger().Warn().Err(err)
}
}
default:
@ -254,15 +254,28 @@ func (node *Node) VerifyNewBlock(newBlock *types.Block) error {
err := node.Blockchain().Validator().ValidateHeader(newBlock, true)
if err != nil {
utils.Logger().Error().
Str("blockHash", newBlock.Hash().Hex()).
Err(err).
Msg("cannot ValidateHeader for the new block")
return ctxerror.New("cannot ValidateHeader for the new block", "blockHash", newBlock.Hash()).WithCause(err)
}
if newBlock.ShardID() != node.Blockchain().ShardID() {
utils.Logger().Error().
Uint32("my shard ID", node.Blockchain().ShardID()).
Uint32("new block's shard ID", newBlock.ShardID()).
Msg("wrong shard ID")
return ctxerror.New("wrong shard ID",
"my shard ID", node.Blockchain().ShardID(),
"new block's shard ID", newBlock.ShardID())
}
err = node.Blockchain().ValidateNewBlock(newBlock)
if err != nil {
utils.Logger().Error().
Str("blockHash", newBlock.Hash().Hex()).
Int("numTx", len(newBlock.Transactions())).
Err(err).
Msg("cannot ValidateNewBlock")
return ctxerror.New("cannot ValidateNewBlock",
"blockHash", newBlock.Hash(),
"numTx", len(newBlock.Transactions()),
@ -282,6 +295,11 @@ func (node *Node) VerifyNewBlock(newBlock *types.Block) error {
// TODO: move into ValidateNewBlock
err = node.verifyIncomingReceipts(newBlock)
if err != nil {
utils.Logger().Error().
Str("blockHash", newBlock.Hash().Hex()).
Int("numIncomingReceipts", len(newBlock.IncomingReceipts())).
Err(err).
Msg("[VerifyNewBlock] Cannot ValidateNewBlock")
return ctxerror.New("[VerifyNewBlock] Cannot ValidateNewBlock", "blockHash", newBlock.Hash(),
"numIncomingReceipts", len(newBlock.IncomingReceipts())).WithCause(err)
}
@ -330,9 +348,6 @@ func (node *Node) PostConsensusProcessing(newBlock *types.Block, commitSigAndBit
utils.Logger().Info().
Uint64("BlockNum", newBlock.NumberU64()).
Msg("BINGO !!! Reached Consensus")
// Print to normal log too
utils.GetLogInstance().Info("BINGO !!! Reached Consensus", "BlockNum", newBlock.NumberU64())
// 15% of the validator also need to do broadcasting
rand.Seed(time.Now().UTC().UnixNano())
rnd := rand.Intn(100)

@ -7,7 +7,6 @@ import (
"github.com/ethereum/go-ethereum/common"
"github.com/harmony-one/harmony/core/types"
"github.com/harmony-one/harmony/internal/ctxerror"
"github.com/harmony-one/harmony/internal/utils"
"github.com/harmony-one/harmony/shard"
"github.com/harmony-one/harmony/shard/committee"
@ -84,9 +83,7 @@ func (node *Node) proposeNewBlock() (*types.Block, error) {
selectedTxs, selectedStakingTxs := node.getTransactionsForNewBlock(coinbase)
if err := node.Worker.CommitTransactions(selectedTxs, selectedStakingTxs, coinbase); err != nil {
ctxerror.Log15(utils.GetLogger().Error,
ctxerror.New("cannot commit transactions").
WithCause(err))
utils.Logger().Error().Err(err).Msg("cannot commit transactions")
return nil, err
}
@ -94,9 +91,7 @@ func (node *Node) proposeNewBlock() (*types.Block, error) {
receiptsList := node.proposeReceiptsProof()
if len(receiptsList) != 0 {
if err := node.Worker.CommitReceipts(receiptsList); err != nil {
ctxerror.Log15(utils.GetLogger().Error,
ctxerror.New("cannot commit receipts").
WithCause(err))
utils.Logger().Error().Err(err).Msg("cannot commit receipts")
}
}
@ -115,9 +110,7 @@ func (node *Node) proposeNewBlock() (*types.Block, error) {
// Prepare last commit signatures
sig, mask, err := node.Consensus.LastCommitSig()
if err != nil {
ctxerror.Log15(utils.GetLogger().Error,
ctxerror.New("Cannot get commit signatures from last block").
WithCause(err))
utils.Logger().Error().Err(err).Msg("Cannot get commit signatures from last block")
return nil, err
}
return node.Worker.FinalizeNewBlock(sig, mask, node.Consensus.GetViewID(), coinbase, crossLinks, shardState)

@ -63,6 +63,7 @@ func (node *Node) validateNewShardState(block *types.Block) error {
)
if err != nil {
utils.Logger().Error().Err(err).Msg("cannot calculate expected shard state")
return ctxerror.New("cannot calculate expected shard state").
WithCause(err)
}
@ -73,8 +74,7 @@ func (node *Node) validateNewShardState(block *types.Block) error {
// TODO ek/chao – calculated shard state is different even with the
// same input, i.e. it is nondeterministic.
// Don't treat this as a blocker until we fix the nondeterminism.
//return err
ctxerror.Log15(utils.GetLogger().Warn, err)
utils.Logger().Warn().Err(err).Msg("shard state proposal is different from expected")
}
} else {
// Regular validators fetch the local-shard copy on the beacon chain
@ -93,6 +93,7 @@ func (node *Node) validateNewShardState(block *types.Block) error {
// Proposal to discontinue shard
if expected != nil {
// TODO ek – invoke view change
utils.Logger().Error().Msg("leader proposed to disband against beacon decision")
return errors.New(
"leader proposed to disband against beacon decision")
}
@ -102,6 +103,10 @@ func (node *Node) validateNewShardState(block *types.Block) error {
// Sanity check: Shard ID should match
if proposed.ShardID != block.ShardID() {
// TODO ek – invoke view change
utils.Logger().Error().
Uint32("proposedShard", proposed.ShardID).
Uint32("blockShard", block.ShardID()).
Msg("proposal has incorrect shard ID")
return ctxerror.New("proposal has incorrect shard ID",
"proposedShard", proposed.ShardID,
"blockShard", block.ShardID())
@ -109,6 +114,8 @@ func (node *Node) validateNewShardState(block *types.Block) error {
// Did beaconchain say we are no more?
if expected == nil {
// TODO ek – invoke view change
utils.Logger().Error().Msg("leader proposed to continue against beacon decision")
return errors.New(
"leader proposed to continue against beacon decision")
}
@ -116,10 +123,14 @@ func (node *Node) validateNewShardState(block *types.Block) error {
if shard.CompareCommittee(expected, &proposed) != 0 {
// TODO ek – log differences
// TODO ek – invoke view change
utils.Logger().Error().Msg("proposal differs from one in beacon chain")
return errors.New("proposal differs from one in beacon chain")
}
default:
// TODO ek – invoke view change
utils.Logger().Error().
Int("numShards", len(proposed)).
Msg("regular resharding proposal has incorrect number of shards")
return ctxerror.New(
"regular resharding proposal has incorrect number of shards",
"numShards", len(proposed))
@ -147,6 +158,7 @@ func (node *Node) broadcastEpochShardState(newBlock *types.Block) error {
func (node *Node) epochShardStateMessageHandler(msgPayload []byte) error {
epochShardState, err := proto_node.DeserializeEpochShardStateFromMessage(msgPayload)
if err != nil {
utils.Logger().Error().Err(err).Msg("Can't get shard state message")
return ctxerror.New("Can't get shard state message").WithCause(err)
}
if node.Consensus == nil {
@ -171,6 +183,9 @@ func (node *Node) epochShardStateMessageHandler(msgPayload []byte) error {
err = node.Beaconchain().WriteShardState(
receivedEpoch, epochShardState.ShardState)
if err != nil {
utils.Logger().Error().
Uint64("epoch", receivedEpoch.Uint64()).
Err(err).Msg("cannot store shard state")
return ctxerror.New("cannot store shard state", "epoch", receivedEpoch).
WithCause(err)
}

@ -430,7 +430,10 @@ func (node *Node) CalculateResponse(request *downloader_pb.DownloaderRequest, in
return response, nil
} else if len(node.peerRegistrationRecord) >= maxBroadcastNodes {
response.Type = downloader_pb.DownloaderResponse_FAIL
utils.GetLogInstance().Debug("[SYNC] maximum registration limit exceeds", "ip", ip, "port", port)
utils.Logger().Debug().
Str("ip", ip).
Str("port", port).
Msg("[SYNC] maximum registration limit exceeds")
return response, nil
} else {
response.Type = downloader_pb.DownloaderResponse_FAIL

Loading…
Cancel
Save