diff --git a/cmd/harmony.go b/cmd/harmony.go index b8a2b4dcd..df52b0d70 100644 --- a/cmd/harmony.go +++ b/cmd/harmony.go @@ -187,14 +187,12 @@ func main() { // Start Profiler for leader if profile argument is on if role == "leader" && (*profile || *metricsReportURL != "") { prof := profiler.GetProfiler() - prof.Config(consensus.Log, shardID, *metricsReportURL) + prof.Config(shardID, *metricsReportURL) if *profile { prof.Start() } } - // Set logger to attack model. - attack.GetInstance().SetLogger(consensus.Log) // Current node. currentNode := node.New(host, consensus, ldb) currentNode.Consensus.OfflinePeers = currentNode.OfflinePeers diff --git a/consensus/consensus.go b/consensus/consensus.go index ee193ba6b..825ba9c2d 100644 --- a/consensus/consensus.go +++ b/consensus/consensus.go @@ -12,7 +12,6 @@ import ( "sync" "github.com/ethereum/go-ethereum/common" - "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/params" "github.com/ethereum/go-ethereum/rlp" "github.com/harmony-one/harmony/core/state" @@ -93,8 +92,6 @@ type Consensus struct { // verified block to state sync broadcast VerifiedNewBlock chan *types.Block - Log log.Logger - uniqueIDInstance *utils.UniqueValidatorID // The p2p host used to send/receive p2p messages @@ -188,7 +185,6 @@ func New(host p2p.Host, ShardID string, peers []p2p.Peer, leader p2p.Peer) *Cons }() } - consensus.Log = log.New() consensus.uniqueIDInstance = utils.GetUniqueValidatorIDInstance() consensus.OfflinePeerList = make([]p2p.Peer, 0) @@ -287,7 +283,7 @@ func (consensus *Consensus) AddPeers(peers []*p2p.Peer) int { consensus.pubKeyLock.Lock() consensus.PublicKeys = append(consensus.PublicKeys, peer.PubKey) consensus.pubKeyLock.Unlock() - consensus.Log.Debug("[SYNC] new peer added", "pubKey", peer.PubKey, "ip", peer.IP, "port", peer.Port) + utils.GetLogInstance().Debug("[SYNC] new peer added", "pubKey", peer.PubKey, "ip", peer.IP, "port", peer.Port) } count++ } @@ -350,10 +346,10 @@ func (consensus *Consensus) RemovePeers(peers []p2p.Peer) int { func (consensus *Consensus) DebugPrintPublicKeys() { for _, k := range consensus.PublicKeys { str := fmt.Sprintf("%s", hex.EncodeToString(k.Serialize())) - consensus.Log.Debug("pk:", "string", str) + utils.GetLogInstance().Debug("pk:", "string", str) } - consensus.Log.Debug("PublicKeys:", "#", len(consensus.PublicKeys)) + utils.GetLogInstance().Debug("PublicKeys:", "#", len(consensus.PublicKeys)) } // DebugPrintValidators print all validator ip/port/key in string format in Consensus @@ -362,13 +358,13 @@ func (consensus *Consensus) DebugPrintValidators() { consensus.validators.Range(func(k, v interface{}) bool { if p, ok := v.(p2p.Peer); ok { str2 := fmt.Sprintf("%s", p.PubKey.Serialize()) - consensus.Log.Debug("validator:", "IP", p.IP, "Port", p.Port, "VID", p.ValidatorID, "Key", str2) + utils.GetLogInstance().Debug("validator:", "IP", p.IP, "Port", p.Port, "VID", p.ValidatorID, "Key", str2) count++ return true } return false }) - consensus.Log.Debug("Validators", "#", count) + utils.GetLogInstance().Debug("Validators", "#", count) } // UpdatePublicKeys updates the PublicKeys variable, protected by a mutex diff --git a/consensus/consensus_leader.go b/consensus/consensus_leader.go index 213fa4904..70e6775eb 100644 --- a/consensus/consensus_leader.go +++ b/consensus/consensus_leader.go @@ -3,6 +3,9 @@ package consensus import ( "bytes" "encoding/hex" + "strconv" + "time" + "github.com/ethereum/go-ethereum/rlp" protobuf "github.com/golang/protobuf/proto" "github.com/harmony-one/bls/ffi/go/bls" @@ -10,10 +13,9 @@ import ( "github.com/harmony-one/harmony/api/services/explorer" "github.com/harmony-one/harmony/core/types" "github.com/harmony-one/harmony/internal/profiler" + "github.com/harmony-one/harmony/internal/utils" "github.com/harmony-one/harmony/p2p" "github.com/harmony-one/harmony/p2p/host" - "strconv" - "time" ) const ( @@ -26,23 +28,23 @@ var ( // WaitForNewBlock waits for the next new block to run consensus on func (consensus *Consensus) WaitForNewBlock(blockChannel chan *types.Block) { - consensus.Log.Debug("Waiting for block", "consensus", consensus) + utils.GetLogInstance().Debug("Waiting for block", "consensus", consensus) for { // keep waiting for new blocks newBlock := <-blockChannel // TODO: think about potential race condition c := consensus.RemovePeers(consensus.OfflinePeerList) if c > 0 { - consensus.Log.Debug("WaitForNewBlock", "removed peers", c) + utils.GetLogInstance().Debug("WaitForNewBlock", "removed peers", c) } for !consensus.HasEnoughValidators() { - consensus.Log.Debug("Not enough validators", "# Validators", len(consensus.PublicKeys)) + utils.GetLogInstance().Debug("Not enough validators", "# Validators", len(consensus.PublicKeys)) time.Sleep(waitForEnoughValidators * time.Millisecond) } startTime = time.Now() - consensus.Log.Debug("STARTING CONSENSUS", "numTxs", len(newBlock.Transactions()), "consensus", consensus, "startTime", startTime, "publicKeys", len(consensus.PublicKeys)) + utils.GetLogInstance().Debug("STARTING CONSENSUS", "numTxs", len(newBlock.Transactions()), "consensus", consensus, "startTime", startTime, "publicKeys", len(consensus.PublicKeys)) for consensus.state == Finished { // time.Sleep(500 * time.Millisecond) consensus.ResetState() @@ -58,7 +60,7 @@ func (consensus *Consensus) ProcessMessageLeader(payload []byte) { err := message.XXX_Unmarshal(payload) if err != nil { - consensus.Log.Error("Failed to unmarshal message payload.", "err", err, "consensus", consensus) + utils.GetLogInstance().Error("Failed to unmarshal message payload.", "err", err, "consensus", consensus) } switch message.Type { @@ -67,7 +69,7 @@ func (consensus *Consensus) ProcessMessageLeader(payload []byte) { case consensus_proto.MessageType_COMMIT: consensus.processCommitMessage(message) default: - consensus.Log.Error("Unexpected message type", "msgType", message.Type, "consensus", consensus) + utils.GetLogInstance().Error("Unexpected message type", "msgType", message.Type, "consensus", consensus) } } @@ -77,16 +79,16 @@ func (consensus *Consensus) startConsensus(newBlock *types.Block) { blockHash := newBlock.Hash() copy(consensus.blockHash[:], blockHash[:]) - consensus.Log.Debug("Start encoding block") + utils.GetLogInstance().Debug("Start encoding block") // prepare message and broadcast to validators encodedBlock, err := rlp.EncodeToBytes(newBlock) if err != nil { - consensus.Log.Debug("Failed encoding block") + utils.GetLogInstance().Debug("Failed encoding block") return } consensus.block = encodedBlock - consensus.Log.Debug("Stop encoding block") + utils.GetLogInstance().Debug("Stop encoding block") msgToSend := consensus.constructAnnounceMessage() // Set state to AnnounceDone @@ -106,19 +108,19 @@ func (consensus *Consensus) processPrepareMessage(message consensus_proto.Messag // Verify signature v, ok := consensus.validators.Load(validatorID) if !ok { - consensus.Log.Warn("Received message from unrecognized validator", "validatorID", validatorID, "consensus", consensus) + utils.GetLogInstance().Warn("Received message from unrecognized validator", "validatorID", validatorID, "consensus", consensus) return } value, ok := v.(p2p.Peer) if !ok { - consensus.Log.Warn("Invalid validator", "validatorID", validatorID, "consensus", consensus) + utils.GetLogInstance().Warn("Invalid validator", "validatorID", validatorID, "consensus", consensus) return } message.Signature = nil messageBytes, err := protobuf.Marshal(&message) if err != nil { - consensus.Log.Warn("Failed to marshal the prepare message", "error", err) + utils.GetLogInstance().Warn("Failed to marshal the prepare message", "error", err) } _ = messageBytes _ = signature @@ -132,12 +134,12 @@ func (consensus *Consensus) processPrepareMessage(message consensus_proto.Messag consensus.mutex.Lock() defer consensus.mutex.Unlock() if consensusID != consensus.consensusID { - consensus.Log.Warn("Received Commit with wrong consensus Id", "myConsensusId", consensus.consensusID, "theirConsensusId", consensusID, "consensus", consensus) + utils.GetLogInstance().Warn("Received Commit with wrong consensus Id", "myConsensusId", consensus.consensusID, "theirConsensusId", consensusID, "consensus", consensus) return } if !bytes.Equal(blockHash, consensus.blockHash[:]) { - consensus.Log.Warn("Received Commit with wrong blockHash", "myConsensusId", consensus.consensusID, "theirConsensusId", consensusID, "consensus", consensus) + utils.GetLogInstance().Warn("Received Commit with wrong blockHash", "myConsensusId", consensus.consensusID, "theirConsensusId", consensusID, "consensus", consensus) return } @@ -155,23 +157,24 @@ func (consensus *Consensus) processPrepareMessage(message consensus_proto.Messag var sign bls.Sign err := sign.Deserialize(prepareSig) if err != nil { - consensus.Log.Error("Failed to deserialize bls signature", "validatorID", validatorID) + utils.GetLogInstance().Error("Failed to deserialize bls signature", "validatorID", validatorID) } // TODO: check bls signature (*prepareSigs)[validatorID] = &sign - consensus.Log.Debug("Received new prepare signature", "numReceivedSoFar", len(*prepareSigs), "validatorID", validatorID, "PublicKeys", len(consensus.PublicKeys)) + utils.GetLogInstance().Debug("Received new prepare signature", "numReceivedSoFar", len(*prepareSigs), "validatorID", validatorID, "PublicKeys", len(consensus.PublicKeys)) + // Set the bitmap indicate this validate signed. prepareBitmap.SetKey(value.PubKey, true) } if !shouldProcess { - consensus.Log.Debug("Received additional new commit message", "validatorID", validatorID) + utils.GetLogInstance().Debug("Received additional new commit message", "validatorID", validatorID) return } targetState := PreparedDone if len((*prepareSigs)) >= ((len(consensus.PublicKeys)*2)/3+1) && consensus.state < targetState { - consensus.Log.Debug("Enough commitments received with signatures", "num", len(*prepareSigs), "state", consensus.state) + utils.GetLogInstance().Debug("Enough commitments received with signatures", "num", len(*prepareSigs), "state", consensus.state) // Construct prepared message msgToSend, aggSig := consensus.constructPreparedMessage() @@ -200,29 +203,29 @@ func (consensus *Consensus) processCommitMessage(message consensus_proto.Message // check consensus Id if consensusID != consensus.consensusID { shouldProcess = false - consensus.Log.Warn("Received Response with wrong consensus Id", "myConsensusId", consensus.consensusID, "theirConsensusId", consensusID, "consensus", consensus) + utils.GetLogInstance().Warn("Received Response with wrong consensus Id", "myConsensusId", consensus.consensusID, "theirConsensusId", consensusID, "consensus", consensus) } if !bytes.Equal(blockHash, consensus.blockHash[:]) { - consensus.Log.Warn("Received Response with wrong blockHash", "myConsensusId", consensus.consensusID, "theirConsensusId", consensusID, "consensus", consensus) + utils.GetLogInstance().Warn("Received Response with wrong blockHash", "myConsensusId", consensus.consensusID, "theirConsensusId", consensusID, "consensus", consensus) return } // Verify signature v, ok := consensus.validators.Load(validatorID) if !ok { - consensus.Log.Warn("Received message from unrecognized validator", "validatorID", validatorID, "consensus", consensus) + utils.GetLogInstance().Warn("Received message from unrecognized validator", "validatorID", validatorID, "consensus", consensus) return } value, ok := v.(p2p.Peer) if !ok { - consensus.Log.Warn("Invalid validator", "validatorID", validatorID, "consensus", consensus) + utils.GetLogInstance().Warn("Invalid validator", "validatorID", validatorID, "consensus", consensus) return } message.Signature = nil messageBytes, err := protobuf.Marshal(&message) if err != nil { - consensus.Log.Warn("Failed to marshal the commit message", "error", err) + utils.GetLogInstance().Warn("Failed to marshal the commit message", "error", err) } _ = messageBytes _ = signature @@ -247,24 +250,24 @@ func (consensus *Consensus) processCommitMessage(message consensus_proto.Message var sign bls.Sign err := sign.Deserialize(commitSig) if err != nil { - consensus.Log.Error("Failed to deserialize bls signature", "validatorID", validatorID) + utils.GetLogInstance().Debug("Failed to deserialize bls signature", "validatorID", validatorID) } // TODO: check bls signature (*commitSigs)[validatorID] = &sign - consensus.Log.Debug("Received new commit message", "numReceivedSoFar", len(*commitSigs), "validatorID", strconv.Itoa(int(validatorID))) + utils.GetLogInstance().Debug("Received new commit message", "numReceivedSoFar", len(*commitSigs), "validatorID", strconv.Itoa(int(validatorID))) // Set the bitmap indicate this validate signed. commitBitmap.SetKey(value.PubKey, true) } if !shouldProcess { - consensus.Log.Debug("Received additional new commit message", "validatorID", strconv.Itoa(int(validatorID))) + utils.GetLogInstance().Debug("Received additional new commit message", "validatorID", strconv.Itoa(int(validatorID))) return } threshold := 2 targetState := CommitDone if len(*commitSigs) >= ((len(consensus.PublicKeys)*threshold)/3+1) && consensus.state != targetState { - consensus.Log.Debug("Enough commits received!", "num", len(*commitSigs), "state", consensus.state) + utils.GetLogInstance().Info("Enough commits received!", "num", len(*commitSigs), "state", consensus.state) // Construct committed message msgToSend, aggSig := consensus.constructCommittedMessage() @@ -279,7 +282,7 @@ func (consensus *Consensus) processCommitMessage(message consensus_proto.Message var blockObj types.Block err = rlp.DecodeBytes(consensus.block, &blockObj) if err != nil { - consensus.Log.Debug("failed to construct the new block after consensus") + utils.GetLogInstance().Debug("failed to construct the new block after consensus") } // Sign the block @@ -291,7 +294,7 @@ func (consensus *Consensus) processCommitMessage(message consensus_proto.Message select { case consensus.VerifiedNewBlock <- &blockObj: default: - consensus.Log.Info("[SYNC] consensus verified block send to chan failed", "blockHash", blockObj.Hash()) + utils.GetLogInstance().Info("[SYNC] consensus verified block send to chan failed", "blockHash", blockObj.Hash()) } consensus.reportMetrics(blockObj) @@ -303,7 +306,7 @@ func (consensus *Consensus) processCommitMessage(message consensus_proto.Message consensus.ResetState() consensus.consensusID++ - consensus.Log.Debug("HOORAY!!! CONSENSUS REACHED!!!", "consensusID", consensus.consensusID, "numOfSignatures", len(*commitSigs)) + utils.GetLogInstance().Debug("HOORAY!!! CONSENSUS REACHED!!!", "consensusID", consensus.consensusID, "numOfSignatures", len(*commitSigs)) // TODO: remove this temporary delay time.Sleep(500 * time.Millisecond) @@ -318,7 +321,7 @@ func (consensus *Consensus) reportMetrics(block types.Block) { timeElapsed := endTime.Sub(startTime) numOfTxs := len(block.Transactions()) tps := float64(numOfTxs) / timeElapsed.Seconds() - consensus.Log.Info("TPS Report", + utils.GetLogInstance().Info("TPS Report", "numOfTXs", numOfTxs, "startTime", startTime, "endTime", endTime, diff --git a/consensus/consensus_leader_msg.go b/consensus/consensus_leader_msg.go index fb51ed3b1..154c24bf7 100644 --- a/consensus/consensus_leader_msg.go +++ b/consensus/consensus_leader_msg.go @@ -7,6 +7,7 @@ import ( consensus_proto "github.com/harmony-one/harmony/api/consensus" "github.com/harmony-one/harmony/api/proto" bls_cosi "github.com/harmony-one/harmony/crypto/bls" + "github.com/harmony-one/harmony/internal/utils" ) // Constructs the announce message @@ -28,7 +29,7 @@ func (consensus *Consensus) constructAnnounceMessage() []byte { marshaledMessage, err := protobuf.Marshal(&message) if err != nil { - consensus.Log.Debug("Failed to marshal Announce message", "error", err) + utils.GetLogInstance().Debug("Failed to marshal Announce message", "error", err) } // 64 byte of signature on previous data signature := consensus.signMessage(marshaledMessage) @@ -36,9 +37,9 @@ func (consensus *Consensus) constructAnnounceMessage() []byte { marshaledMessage, err = protobuf.Marshal(&message) if err != nil { - consensus.Log.Debug("Failed to marshal Announce message", "error", err) + utils.GetLogInstance().Debug("Failed to marshal Announce message", "error", err) } - consensus.Log.Info("New Announce", "NodeID", consensus.nodeID) + utils.GetLogInstance().Info("New Announce", "NodeID", consensus.nodeID) return proto.ConstructConsensusMessage(marshaledMessage) } @@ -72,7 +73,7 @@ func (consensus *Consensus) constructPreparedMessage() ([]byte, *bls.Sign) { // TODO: use custom serialization method rather than protobuf marshaledMessage, err := protobuf.Marshal(&message) if err != nil { - consensus.Log.Debug("Failed to marshal Prepared message", "error", err) + utils.GetLogInstance().Debug("Failed to marshal Prepared message", "error", err) } // 48 byte of signature on previous data signature := consensus.signMessage(marshaledMessage) @@ -80,9 +81,9 @@ func (consensus *Consensus) constructPreparedMessage() ([]byte, *bls.Sign) { marshaledMessage, err = protobuf.Marshal(&message) if err != nil { - consensus.Log.Debug("Failed to marshal Prepared message", "error", err) + utils.GetLogInstance().Debug("Failed to marshal Prepared message", "error", err) } - consensus.Log.Info("New Prepared Message", "NodeID", consensus.nodeID, "bitmap", consensus.prepareBitmap) + utils.GetLogInstance().Info("New Prepared Message", "NodeID", consensus.nodeID, "bitmap", consensus.prepareBitmap) return proto.ConstructConsensusMessage(marshaledMessage), aggSig } @@ -115,7 +116,7 @@ func (consensus *Consensus) constructCommittedMessage() ([]byte, *bls.Sign) { // TODO: use custom serialization method rather than protobuf marshaledMessage, err := protobuf.Marshal(&message) if err != nil { - consensus.Log.Debug("Failed to marshal Committed message", "error", err) + utils.GetLogInstance().Debug("Failed to marshal Committed message", "error", err) } // 48 byte of signature on previous data signature := consensus.signMessage(marshaledMessage) @@ -123,8 +124,8 @@ func (consensus *Consensus) constructCommittedMessage() ([]byte, *bls.Sign) { marshaledMessage, err = protobuf.Marshal(&message) if err != nil { - consensus.Log.Debug("Failed to marshal Committed message", "error", err) + utils.GetLogInstance().Debug("Failed to marshal Committed message", "error", err) } - consensus.Log.Info("New Prepared Message", "NodeID", consensus.nodeID, "bitmap", consensus.commitBitmap) + utils.GetLogInstance().Info("New Prepared Message", "NodeID", consensus.nodeID, "bitmap", consensus.commitBitmap) return proto.ConstructConsensusMessage(marshaledMessage), aggSig } diff --git a/consensus/consensus_validator.go b/consensus/consensus_validator.go index 1faa18c63..e190ad96e 100644 --- a/consensus/consensus_validator.go +++ b/consensus/consensus_validator.go @@ -17,7 +17,7 @@ func (consensus *Consensus) ProcessMessageValidator(payload []byte) { err := protobuf.Unmarshal(payload, &message) if err != nil { - consensus.Log.Error("Failed to unmarshal message payload.", "err", err, "consensus", consensus) + utils.GetLogInstance().Error("Failed to unmarshal message payload.", "err", err, "consensus", consensus) } switch message.Type { case consensus_proto.MessageType_ANNOUNCE: @@ -27,13 +27,13 @@ func (consensus *Consensus) ProcessMessageValidator(payload []byte) { case consensus_proto.MessageType_COMMITTED: consensus.processCommittedMessage(message) default: - consensus.Log.Error("Unexpected message type", "msgType", message.Type, "consensus", consensus) + utils.GetLogInstance().Error("Unexpected message type", "msgType", message.Type, "consensus", consensus) } } // Processes the announce message sent from the leader func (consensus *Consensus) processAnnounceMessage(message consensus_proto.Message) { - consensus.Log.Info("Received Announce Message", "nodeID", consensus.nodeID) + utils.GetLogInstance().Info("Received Announce Message", "nodeID", consensus.nodeID) consensusID := message.ConsensusId blockHash := message.BlockHash @@ -47,7 +47,7 @@ func (consensus *Consensus) processAnnounceMessage(message consensus_proto.Messa // check leader Id myLeaderID := utils.GetUniqueIDFromPeer(consensus.leader) if leaderID != myLeaderID { - consensus.Log.Warn("Received message from wrong leader", "myLeaderID", myLeaderID, "receivedLeaderId", leaderID, "consensus", consensus) + utils.GetLogInstance().Warn("Received message from wrong leader", "myLeaderID", myLeaderID, "receivedLeaderId", leaderID, "consensus", consensus) return } @@ -55,7 +55,7 @@ func (consensus *Consensus) processAnnounceMessage(message consensus_proto.Messa message.Signature = nil messageBytes, err := protobuf.Marshal(&message) if err != nil { - consensus.Log.Warn("Failed to marshal the announce message", "error", err) + utils.GetLogInstance().Warn("Failed to marshal the announce message", "error", err) } _ = signature _ = messageBytes @@ -69,7 +69,7 @@ func (consensus *Consensus) processAnnounceMessage(message consensus_proto.Messa var blockObj types.Block err = rlp.DecodeBytes(block, &blockObj) if err != nil { - consensus.Log.Warn("Unparseable block header data", "error", err) + utils.GetLogInstance().Warn("Unparseable block header data", "error", err) return } @@ -82,20 +82,20 @@ func (consensus *Consensus) processAnnounceMessage(message consensus_proto.Messa // Add attack model of IncorrectResponse if attack.GetInstance().IncorrectResponse() { - consensus.Log.Warn("IncorrectResponse attacked") + utils.GetLogInstance().Warn("IncorrectResponse attacked") return } // check block hash hash := blockObj.Hash() if !bytes.Equal(blockHash[:], hash[:]) { - consensus.Log.Warn("Block hash doesn't match", "consensus", consensus) + utils.GetLogInstance().Warn("Block hash doesn't match", "consensus", consensus) return } // check block data (transactions if !consensus.BlockVerifier(&blockObj) { - consensus.Log.Warn("Block content is not verified successfully", "consensus", consensus) + utils.GetLogInstance().Warn("Block content is not verified successfully", "consensus", consensus) return } @@ -103,7 +103,7 @@ func (consensus *Consensus) processAnnounceMessage(message consensus_proto.Messa msgToSend := consensus.constructPrepareMessage() consensus.SendMessage(consensus.leader, msgToSend) - // consensus.Log.Warn("Sending Commit to leader", "state", targetState) + // utils.GetLogInstance().Warn("Sending Commit to leader", "state", targetState) // Set state to CommitDone consensus.state = PrepareDone @@ -111,7 +111,7 @@ func (consensus *Consensus) processAnnounceMessage(message consensus_proto.Messa // Processes the prepared message sent from the leader func (consensus *Consensus) processPreparedMessage(message consensus_proto.Message) { - consensus.Log.Info("Received Prepared Message", "nodeID", consensus.nodeID) + utils.GetLogInstance().Info("Received Prepared Message", "nodeID", consensus.nodeID) consensusID := message.ConsensusId blockHash := message.BlockHash @@ -135,7 +135,7 @@ func (consensus *Consensus) processPreparedMessage(message consensus_proto.Messa // check leader Id myLeaderID := utils.GetUniqueIDFromPeer(consensus.leader) if uint32(leaderID) != myLeaderID { - consensus.Log.Warn("Received message from wrong leader", "myLeaderID", myLeaderID, "receivedLeaderId", leaderID, "consensus", consensus) + utils.GetLogInstance().Warn("Received message from wrong leader", "myLeaderID", myLeaderID, "receivedLeaderId", leaderID, "consensus", consensus) return } @@ -143,7 +143,7 @@ func (consensus *Consensus) processPreparedMessage(message consensus_proto.Messa message.Signature = nil messageBytes, err := protobuf.Marshal(&message) if err != nil { - consensus.Log.Warn("Failed to marshal the announce message", "error", err) + utils.GetLogInstance().Warn("Failed to marshal the announce message", "error", err) } _ = signature _ = messageBytes @@ -155,7 +155,7 @@ func (consensus *Consensus) processPreparedMessage(message consensus_proto.Messa // Add attack model of IncorrectResponse. if attack.GetInstance().IncorrectResponse() { - consensus.Log.Warn("IncorrectResponse attacked") + utils.GetLogInstance().Warn("IncorrectResponse attacked") return } @@ -164,7 +164,7 @@ func (consensus *Consensus) processPreparedMessage(message consensus_proto.Messa // check block hash if !bytes.Equal(blockHash[:], consensus.blockHash[:]) { - consensus.Log.Warn("Block hash doesn't match", "consensus", consensus) + utils.GetLogInstance().Warn("Block hash doesn't match", "consensus", consensus) return } @@ -182,7 +182,7 @@ func (consensus *Consensus) processPreparedMessage(message consensus_proto.Messa // Processes the committed message sent from the leader func (consensus *Consensus) processCommittedMessage(message consensus_proto.Message) { - consensus.Log.Info("Received Prepared Message", "nodeID", consensus.nodeID) + utils.GetLogInstance().Warn("Received Prepared Message", "nodeID", consensus.nodeID) consensusID := message.ConsensusId blockHash := message.BlockHash @@ -206,7 +206,7 @@ func (consensus *Consensus) processCommittedMessage(message consensus_proto.Mess // check leader Id myLeaderID := utils.GetUniqueIDFromPeer(consensus.leader) if uint32(leaderID) != myLeaderID { - consensus.Log.Warn("Received message from wrong leader", "myLeaderID", myLeaderID, "receivedLeaderId", leaderID, "consensus", consensus) + utils.GetLogInstance().Warn("Received message from wrong leader", "myLeaderID", myLeaderID, "receivedLeaderId", leaderID, "consensus", consensus) return } @@ -214,7 +214,7 @@ func (consensus *Consensus) processCommittedMessage(message consensus_proto.Mess message.Signature = nil messageBytes, err := protobuf.Marshal(&message) if err != nil { - consensus.Log.Warn("Failed to marshal the announce message", "error", err) + utils.GetLogInstance().Warn("Failed to marshal the announce message", "error", err) } _ = signature _ = messageBytes @@ -226,16 +226,23 @@ func (consensus *Consensus) processCommittedMessage(message consensus_proto.Mess // Add attack model of IncorrectResponse. if attack.GetInstance().IncorrectResponse() { - consensus.Log.Warn("IncorrectResponse attacked") + utils.GetLogInstance().Warn("IncorrectResponse attacked") return } consensus.mutex.Lock() defer consensus.mutex.Unlock() + // check consensus Id + if consensusID != consensus.consensusID { + // hack for new node state syncing + utils.GetLogInstance().Warn("Received message with wrong consensus Id", "myConsensusId", consensus.consensusID, "theirConsensusId", consensusID, "consensus", consensus) + consensus.consensusID = consensusID + return + } // check block hash if !bytes.Equal(blockHash[:], consensus.blockHash[:]) { - consensus.Log.Warn("Block hash doesn't match", "consensus", consensus) + utils.GetLogInstance().Warn("Block hash doesn't match", "consensus", consensus) return } @@ -263,24 +270,24 @@ func (consensus *Consensus) processCommittedMessage(message consensus_proto.Mess var blockObj types.Block err := rlp.DecodeBytes(val.block, &blockObj) if err != nil { - consensus.Log.Warn("Unparseable block header data", "error", err) + utils.GetLogInstance().Warn("Unparseable block header data", "error", err) return } if err != nil { - consensus.Log.Debug("failed to construct the new block after consensus") + utils.GetLogInstance().Debug("failed to construct the new block after consensus") } // check block data (transactions if !consensus.BlockVerifier(&blockObj) { - consensus.Log.Debug("[WARNING] Block content is not verified successfully", "consensusID", consensus.consensusID) + utils.GetLogInstance().Debug("[WARNING] Block content is not verified successfully", "consensusID", consensus.consensusID) return } - consensus.Log.Info("Finished Response. Adding block to chain", "numTx", len(blockObj.Transactions())) + utils.GetLogInstance().Info("Finished Response. Adding block to chain", "numTx", len(blockObj.Transactions())) consensus.OnConsensusDone(&blockObj) select { case consensus.VerifiedNewBlock <- &blockObj: default: - consensus.Log.Info("[SYNC] consensus verified block send to chan failed", "blockHash", blockObj.Hash()) + utils.GetLogInstance().Info("[SYNC] consensus verified block send to chan failed", "blockHash", blockObj.Hash()) continue } diff --git a/consensus/consensus_validator_msg.go b/consensus/consensus_validator_msg.go index 82e909873..cf626babe 100644 --- a/consensus/consensus_validator_msg.go +++ b/consensus/consensus_validator_msg.go @@ -4,6 +4,7 @@ import ( protobuf "github.com/golang/protobuf/proto" consensus_proto "github.com/harmony-one/harmony/api/consensus" "github.com/harmony-one/harmony/api/proto" + "github.com/harmony-one/harmony/internal/utils" ) // Construct the prepare message to send to leader (assumption the consensus data is already verified) @@ -28,7 +29,7 @@ func (consensus *Consensus) constructPrepareMessage() []byte { marshaledMessage, err := protobuf.Marshal(&message) if err != nil { - consensus.Log.Debug("Failed to marshal Prepare message", "error", err) + utils.GetLogInstance().Debug("Failed to marshal Prepare message", "error", err) } // 64 byte of signature on previous data signature := consensus.signMessage(marshaledMessage) @@ -36,7 +37,7 @@ func (consensus *Consensus) constructPrepareMessage() []byte { marshaledMessage, err = protobuf.Marshal(&message) if err != nil { - consensus.Log.Debug("Failed to marshal Prepare message", "error", err) + utils.GetLogInstance().Debug("Failed to marshal Prepare message", "error", err) } return proto.ConstructConsensusMessage(marshaledMessage) @@ -65,7 +66,7 @@ func (consensus *Consensus) constructCommitMessage() []byte { marshaledMessage, err := protobuf.Marshal(&message) if err != nil { - consensus.Log.Debug("Failed to marshal Commit message", "error", err) + utils.GetLogInstance().Debug("Failed to marshal Commit message", "error", err) } // 64 byte of signature on previous data signature := consensus.signMessage(marshaledMessage) @@ -73,7 +74,7 @@ func (consensus *Consensus) constructCommitMessage() []byte { marshaledMessage, err = protobuf.Marshal(&message) if err != nil { - consensus.Log.Debug("Failed to marshal Commit message", "error", err) + utils.GetLogInstance().Debug("Failed to marshal Commit message", "error", err) } return proto.ConstructConsensusMessage(marshaledMessage) diff --git a/internal/attack/attack.go b/internal/attack/attack.go index 56d499206..1495f36a0 100644 --- a/internal/attack/attack.go +++ b/internal/attack/attack.go @@ -6,7 +6,7 @@ import ( "sync" "time" - "github.com/ethereum/go-ethereum/log" + "github.com/harmony-one/harmony/internal/utils" ) // Constants used for attack model. @@ -34,7 +34,6 @@ type Model struct { attackType Type ConsensusIDThreshold uint32 readyByConsensusThreshold bool - log log.Logger // Log utility } var attackModel *Model @@ -64,11 +63,6 @@ func (attack *Model) SetAttackEnabled(AttackEnabled bool) { } } -// SetLogger sets the logger for doing logging. -func (attack *Model) SetLogger(log log.Logger) { - attack.log = log -} - // Run runs enabled attacks. func (attack *Model) Run() { attack.NodeKilledByItSelf() @@ -82,7 +76,7 @@ func (attack *Model) NodeKilledByItSelf() { } if rand.Intn(HitRate) == 0 { - attack.log.Debug("******************Killing myself******************", "PID: ", os.Getpid()) + utils.GetLogInstance().Debug("******************Killing myself******************", "PID: ", os.Getpid()) os.Exit(1) } } @@ -93,7 +87,7 @@ func (attack *Model) DelayResponse() { return } if rand.Intn(HitRate) == 0 { - attack.log.Debug("******************Model: DelayResponse******************", "PID: ", os.Getpid()) + utils.GetLogInstance().Debug("******************Model: DelayResponse******************", "PID: ", os.Getpid()) time.Sleep(DelayResponseDuration) } } @@ -104,7 +98,7 @@ func (attack *Model) IncorrectResponse() bool { return false } if rand.Intn(HitRate) == 0 { - attack.log.Debug("******************Model: IncorrectResponse******************", "PID: ", os.Getpid()) + utils.GetLogInstance().Debug("******************Model: IncorrectResponse******************", "PID: ", os.Getpid()) return true } return false diff --git a/internal/attack/attack_test.go b/internal/attack/attack_test.go index f909296a6..f0980f4d6 100644 --- a/internal/attack/attack_test.go +++ b/internal/attack/attack_test.go @@ -3,7 +3,6 @@ package attack import ( "testing" - "github.com/ethereum/go-ethereum/log" "github.com/stretchr/testify/assert" ) @@ -17,7 +16,6 @@ func TestIncorrectResponse(t *testing.T) { // Simple test for UpdateConsensusReady func TestUpdateConsensusReady(t *testing.T) { model := GetInstance() - model.SetLogger(log.New()) model.NodeKilledByItSelf() model.UpdateConsensusReady(model.ConsensusIDThreshold - 1) diff --git a/internal/beaconchain/libs/beaconchain.go b/internal/beaconchain/libs/beaconchain.go index d5e8fba25..fad6283cc 100644 --- a/internal/beaconchain/libs/beaconchain.go +++ b/internal/beaconchain/libs/beaconchain.go @@ -7,7 +7,6 @@ import ( "strconv" "sync" - "github.com/ethereum/go-ethereum/log" "github.com/harmony-one/harmony/api/proto/bcconn" proto_identity "github.com/harmony-one/harmony/api/proto/identity" "github.com/harmony-one/harmony/api/proto/node" @@ -43,7 +42,6 @@ type BCInfo struct { // BeaconChain (Blockchain) keeps Identities per epoch, currently centralized! type BeaconChain struct { BCInfo BCInfo - log log.Logger ShardLeaderMap map[int]*node.Info PubKey *bls.PublicKey host p2p.Host @@ -79,7 +77,7 @@ func (bc *BeaconChain) StartRPCServer() { if err != nil { port = 0 } - bc.log.Info("support_client: StartRpcServer on port:", "port", strconv.Itoa(port+BeaconchainServicePortDiff)) + utils.GetLogInstance().Info("support_client: StartRpcServer on port:", "port", strconv.Itoa(port+BeaconchainServicePortDiff)) bc.rpcServer.Start(bc.BCInfo.IP, strconv.Itoa(port+BeaconchainServicePortDiff)) } @@ -95,7 +93,6 @@ func (bc *BeaconChain) GetShardLeaderMap() map[int]*node.Info { //New beaconchain initialization func New(numShards int, ip, port string, key p2p_crypto.PrivKey) *BeaconChain { bc := BeaconChain{} - bc.log = log.New() bc.PubKey = generateBCKey() bc.Self = p2p.Peer{IP: ip, Port: port} bc.host, _ = p2pimpl.NewHost(&bc.Self, key) @@ -117,7 +114,7 @@ func generateBCKey() *bls.PublicKey { //AcceptNodeInfo deserializes node information received via beaconchain handler func (bc *BeaconChain) AcceptNodeInfo(b []byte) *node.Info { Node := bcconn.DeserializeNodeInfo(b) - bc.log.Info("New Node Connection", "IP", Node.IP, "Port", Node.Port, "PeerID", Node.PeerID) + utils.GetLogInstance().Info("New Node Connection", "IP", Node.IP, "Port", Node.Port, "PeerID", Node.PeerID) bc.Peer = p2p.Peer{IP: Node.IP, Port: Node.Port, PeerID: Node.PeerID} bc.host.AddPeer(&bc.Peer) @@ -138,9 +135,9 @@ func (bc *BeaconChain) RespondRandomness(Node *node.Info) { response := bcconn.ResponseRandomNumber{NumberOfShards: bci.NumberOfShards, NumberOfNodesAdded: bci.NumberOfNodesAdded, Leaders: bci.Leaders} msg := bcconn.SerializeRandomInfo(response) msgToSend := proto_identity.ConstructIdentityMessage(proto_identity.Acknowledge, msg) - bc.log.Info("Sent Out Msg", "# Nodes", response.NumberOfNodesAdded) + utils.GetLogInstance().Info("Sent Out Msg", "# Nodes", response.NumberOfNodesAdded) for i, n := range response.Leaders { - bc.log.Info("Sent Out Msg", "leader", i, "nodeInfo", n.PeerID) + utils.GetLogInstance().Info("Sent Out Msg", "leader", i, "nodeInfo", n.PeerID) } host.SendMessage(bc.host, bc.Peer, msgToSend, nil) bc.state = RandomInfoSent diff --git a/internal/beaconchain/libs/beaconchain_handler.go b/internal/beaconchain/libs/beaconchain_handler.go index c94708037..b2dffc35f 100644 --- a/internal/beaconchain/libs/beaconchain_handler.go +++ b/internal/beaconchain/libs/beaconchain_handler.go @@ -3,6 +3,7 @@ package beaconchain import ( "github.com/harmony-one/harmony/api/proto" proto_identity "github.com/harmony-one/harmony/api/proto/identity" + "github.com/harmony-one/harmony/internal/utils" "github.com/harmony-one/harmony/p2p" ) @@ -10,27 +11,27 @@ import ( func (bc *BeaconChain) BeaconChainHandler(s p2p.Stream) { content, err := p2p.ReadMessageContent(s) if err != nil { - bc.log.Error("Read p2p data failed") + utils.GetLogInstance().Error("Read p2p data failed") return } msgCategory, err := proto.GetMessageCategory(content) if err != nil { - bc.log.Error("Read message category failed", "err", err) + utils.GetLogInstance().Error("Read message category failed", "err", err) return } msgType, err := proto.GetMessageType(content) if err != nil { - bc.log.Error("Read action type failed") + utils.GetLogInstance().Error("Read action type failed") return } msgPayload, err := proto.GetMessagePayload(content) if err != nil { - bc.log.Error("Read message payload failed") + utils.GetLogInstance().Error("Read message payload failed") return } identityMsgPayload, err := proto_identity.GetIdentityMessagePayload(msgPayload) if err != nil { - bc.log.Error("Read message payload failed") + utils.GetLogInstance().Error("Read message payload failed") return } switch msgCategory { @@ -38,20 +39,20 @@ func (bc *BeaconChain) BeaconChainHandler(s p2p.Stream) { actionType := proto_identity.IDMessageType(msgType) switch actionType { case proto_identity.Identity: - bc.log.Info("Message category is of the type identity protocol, which is correct!") + utils.GetLogInstance().Info("Message category is of the type identity protocol, which is correct!") idMsgType, err := proto_identity.GetIdentityMessageType(msgPayload) if err != nil { - bc.log.Error("Error finding the identity message type") + utils.GetLogInstance().Error("Error finding the identity message type") } switch idMsgType { case proto_identity.Register: - bc.log.Info("Identity Message Type is of the type Register") + utils.GetLogInstance().Info("Identity Message Type is of the type Register") bc.AcceptConnections(identityMsgPayload) default: - bc.log.Error("Unrecognized identity message type", "type", idMsgType) + utils.GetLogInstance().Error("Unrecognized identity message type", "type", idMsgType) } default: - bc.log.Error("Unrecognized message category", "actionType", actionType) + utils.GetLogInstance().Error("Unrecognized message category", "actionType", actionType) } } diff --git a/internal/profiler/profiler.go b/internal/profiler/profiler.go index 99445b1dd..6cfc19b9a 100644 --- a/internal/profiler/profiler.go +++ b/internal/profiler/profiler.go @@ -8,14 +8,12 @@ import ( "sync" "time" - "github.com/ethereum/go-ethereum/log" + "github.com/harmony-one/harmony/internal/utils" "github.com/shirou/gopsutil/process" ) // Profiler is the profiler data structure. type Profiler struct { - // parameters - logger log.Logger pid int32 shardID string MetricsReportURL string @@ -36,8 +34,7 @@ func GetProfiler() *Profiler { } // Config configurates Profiler. -func (profiler *Profiler) Config(logger log.Logger, shardID string, metricsReportURL string) { - profiler.logger = logger +func (profiler *Profiler) Config(shardID string, metricsReportURL string) { profiler.pid = int32(os.Getpid()) profiler.shardID = shardID profiler.MetricsReportURL = metricsReportURL @@ -49,7 +46,7 @@ func (profiler *Profiler) LogMemory() { // log mem usage info, _ := profiler.proc.MemoryInfo() memMap, _ := profiler.proc.MemoryMaps(false) - profiler.logger.Info("Mem Report", "info", info, "map", memMap, "shardID", profiler.shardID) + utils.GetLogInstance().Info("Mem Report", "info", info, "map", memMap, "shardID", profiler.shardID) time.Sleep(3 * time.Second) } @@ -61,7 +58,7 @@ func (profiler *Profiler) LogCPU() { // log cpu usage percent, _ := profiler.proc.CPUPercent() times, _ := profiler.proc.Times() - profiler.logger.Info("CPU Report", "percent", percent, "times", times, "shardID", profiler.shardID) + utils.GetLogInstance().Info("CPU Report", "percent", percent, "times", times, "shardID", profiler.shardID) time.Sleep(3 * time.Second) } diff --git a/internal/utils/singleton.go b/internal/utils/singleton.go index a86e242ca..5735e7a7a 100644 --- a/internal/utils/singleton.go +++ b/internal/utils/singleton.go @@ -16,6 +16,7 @@ var ( ) // SetPortAndIP used to print out loggings of node with Port and IP. +// Every instance (node, txgen, etc..) needs to set this for logging. func SetPortAndIP(port, ip string) { Port = port IP = ip diff --git a/node/node.go b/node/node.go index d070441c4..5322c56f8 100644 --- a/node/node.go +++ b/node/node.go @@ -109,8 +109,6 @@ type Node struct { blockchain *core.BlockChain // The blockchain for the shard where this node belongs db *ethdb.LDBDatabase // LevelDB to store blockchain. - log log.Logger // Log utility - ClientPeer *p2p.Peer // The peer for the harmony tx generator client, used for leaders to return proof-of-accept Client *client.Client // The presence of a client object means this node will also act as a client SelfPeer p2p.Peer // TODO(minhdoan): it could be duplicated with Self below whose is Alok work. @@ -156,7 +154,7 @@ func (node *Node) addPendingTransactions(newTxs types.Transactions) { node.pendingTxMutex.Lock() node.pendingTransactions = append(node.pendingTransactions, newTxs...) node.pendingTxMutex.Unlock() - node.log.Debug("Got more transactions", "num", len(newTxs), "totalPending", len(node.pendingTransactions)) + utils.GetLogInstance().Debug("Got more transactions", "num", len(newTxs), "totalPending", len(node.pendingTransactions)) } // Take out a subset of valid transactions from the pending transaction list @@ -166,9 +164,9 @@ func (node *Node) getTransactionsForNewBlock(maxNumTxs int) types.Transactions { selected, unselected, invalid := node.Worker.SelectTransactionsForNewBlock(node.pendingTransactions, maxNumTxs) _ = invalid // invalid txs are discard - node.log.Debug("Invalid transactions discarded", "number", len(invalid)) + utils.GetLogInstance().Debug("Invalid transactions discarded", "number", len(invalid)) node.pendingTransactions = unselected - node.log.Debug("Remaining pending transactions", "number", len(node.pendingTransactions)) + utils.GetLogInstance().Debug("Remaining pending transactions", "number", len(node.pendingTransactions)) node.pendingTxMutex.Unlock() return selected } @@ -198,7 +196,7 @@ func (node *Node) SerializeNode(nnode *NetworkNode) []byte { if err != nil { fmt.Println("Could not serialize node") fmt.Println("ERROR", err) - //node.log.Error("Could not serialize node") + //utils.GetLogInstance().Error("Could not serialize node") } return result.Bytes() @@ -225,9 +223,6 @@ func New(host p2p.Host, consensus *bft.Consensus, db ethdb.Database) *Node { node.SelfPeer = host.GetSelfPeer() } - // Logger - node.log = log.New("IP", host.GetSelfPeer().IP, "Port", host.GetSelfPeer().Port) - if host != nil && consensus != nil { // Consensus and associated channel to communicate blocks node.Consensus = consensus @@ -286,7 +281,7 @@ func New(host p2p.Host, consensus *bft.Consensus, db ethdb.Database) *Node { func (node *Node) IsOutOfSync(consensusBlock *types.Block) bool { myHeight := node.blockchain.CurrentBlock().NumberU64() newHeight := consensusBlock.NumberU64() - node.log.Debug("[SYNC]", "myHeight", myHeight, "newHeight", newHeight) + utils.GetLogInstance().Debug("[SYNC]", "myHeight", myHeight, "newHeight", newHeight) if newHeight-myHeight <= inSyncThreshold { return false } @@ -310,7 +305,7 @@ func (node *Node) DoSyncing() { case consensusBlock := <-node.Consensus.ConsensusBlock: if !node.IsOutOfSync(consensusBlock) { if node.State == NodeNotInSync { - node.log.Info("[SYNC] Node is now IN SYNC!") + utils.GetLogInstance().Info("[SYNC] Node is now IN SYNC!") node.stateSync.CloseConnections() node.stateSync = nil } @@ -319,7 +314,7 @@ func (node *Node) DoSyncing() { node.stateMutex.Unlock() continue } else { - node.log.Debug("[SYNC] node is out of sync") + utils.GetLogInstance().Debug("[SYNC] node is out of sync") node.stateMutex.Lock() node.State = NodeNotInSync node.stateMutex.Unlock() @@ -386,7 +381,7 @@ func (node *Node) GetSyncingPeers() []p2p.Peer { if removeID != -1 { res = append(res[:removeID], res[removeID+1:]...) } - node.log.Debug("GetSyncingPeers: ", "res", res, "self", node.SelfPeer) + utils.GetLogInstance().Debug("GetSyncingPeers: ", "res", res, "self", node.SelfPeer) return res } @@ -442,10 +437,10 @@ func (node *Node) JoinShard(leader p2p.Peer) { // Talk to leader. node.SendMessage(leader, buffer) case <-timeout.C: - node.log.Info("JoinShard timeout") + utils.GetLogInstance().Info("JoinShard timeout") return case <-node.StopPing: - node.log.Info("Stopping JoinShard") + utils.GetLogInstance().Info("Stopping JoinShard") return } } @@ -475,7 +470,7 @@ func (node *Node) InitClientServer() { // StartClientServer starts client server. func (node *Node) StartClientServer() { port, _ := strconv.Atoi(node.SelfPeer.Port) - node.log.Info("support_client: StartClientServer on port:", "port", port+ClientServicePortDiff) + utils.GetLogInstance().Info("support_client: StartClientServer on port:", "port", port+ClientServicePortDiff) node.clientServer.Start(node.SelfPeer.IP, strconv.Itoa(port+ClientServicePortDiff)) } @@ -495,7 +490,7 @@ func (node *Node) InitSyncingServer() { // StartSyncingServer starts syncing server. func (node *Node) StartSyncingServer() { port := GetSyncingPort(node.SelfPeer.Port) - node.log.Info("support_sycning: StartSyncingServer on port:", "port", port) + utils.GetLogInstance().Info("support_sycning: StartSyncingServer on port:", "port", port) node.downloaderServer.Start(node.SelfPeer.IP, GetSyncingPort(node.SelfPeer.Port)) } @@ -504,7 +499,7 @@ func (node *Node) CalculateResponse(request *downloader_pb.DownloaderRequest) (* response := &downloader_pb.DownloaderResponse{} switch request.Type { case downloader_pb.DownloaderRequest_HEADER: - node.log.Debug("[SYNC] CalculateResponse DownloaderRequest_HEADER", "request.BlockHash", request.BlockHash) + utils.GetLogInstance().Debug("[SYNC] CalculateResponse DownloaderRequest_HEADER", "request.BlockHash", request.BlockHash) var startHeaderHash []byte if request.BlockHash == nil { tmp := node.blockchain.Genesis().Hash() @@ -531,14 +526,14 @@ func (node *Node) CalculateResponse(request *downloader_pb.DownloaderRequest) (* } case downloader_pb.DownloaderRequest_NEWBLOCK: if node.State != NodeNotInSync { - node.log.Debug("[SYNC] new block received, but state is", "state", node.State.String()) + utils.GetLogInstance().Debug("[SYNC] new block received, but state is", "state", node.State.String()) response.Type = downloader_pb.DownloaderResponse_INSYNC return response, nil } var blockObj types.Block err := rlp.DecodeBytes(request.BlockHash, &blockObj) if err != nil { - node.log.Warn("[SYNC] unable to decode received new block") + utils.GetLogInstance().Warn("[SYNC] unable to decode received new block") return response, err } node.stateSync.AddNewBlock(request.PeerHash, &blockObj) @@ -554,25 +549,25 @@ func (node *Node) CalculateResponse(request *downloader_pb.DownloaderRequest) (* } else { peer, ok := node.Consensus.GetPeerFromID(peerID) if !ok { - node.log.Warn("[SYNC] unable to get peer from peerID", "peerID", peerID) + utils.GetLogInstance().Warn("[SYNC] unable to get peer from peerID", "peerID", peerID) } client := downloader.ClientSetup(peer.IP, GetSyncingPort(peer.Port)) if client == nil { - node.log.Warn("[SYNC] unable to setup client") + utils.GetLogInstance().Warn("[SYNC] unable to setup client") return response, nil } - node.log.Debug("[SYNC] client setup correctly", "client", client) + utils.GetLogInstance().Debug("[SYNC] client setup correctly", "client", client) config := &syncConfig{timestamp: time.Now().UnixNano(), client: client} node.stateMutex.Lock() node.peerRegistrationRecord[peerID] = config node.stateMutex.Unlock() - node.log.Debug("[SYNC] register peerID success", "peerID", peerID) + utils.GetLogInstance().Debug("[SYNC] register peerID success", "peerID", peerID) response.Type = downloader_pb.DownloaderResponse_SUCCESS } case downloader_pb.DownloaderRequest_REGISTERTIMEOUT: if node.State == NodeNotInSync { count := node.stateSync.RegisterNodeInfo() - node.log.Debug("[SYNC] extra node registered", "number", count) + utils.GetLogInstance().Debug("[SYNC] extra node registered", "number", count) } } return response, nil @@ -584,18 +579,18 @@ func (node *Node) SendNewBlockToUnsync() { block := <-node.Consensus.VerifiedNewBlock blockHash, err := rlp.EncodeToBytes(block) if err != nil { - node.log.Warn("[SYNC] unable to encode block to hashes") + utils.GetLogInstance().Warn("[SYNC] unable to encode block to hashes") continue } // really need to have a unique id independent of ip/port selfPeerID := utils.GetUniqueIDFromIPPort(node.SelfPeer.IP, node.SelfPeer.Port) - node.log.Debug("[SYNC] peerRegistration Record", "peerID", selfPeerID, "number", len(node.peerRegistrationRecord)) + utils.GetLogInstance().Debug("[SYNC] peerRegistration Record", "peerID", selfPeerID, "number", len(node.peerRegistrationRecord)) for peerID, config := range node.peerRegistrationRecord { elapseTime := time.Now().UnixNano() - config.timestamp if elapseTime > broadcastTimeout { - node.log.Warn("[SYNC] SendNewBlockToUnsync to peer timeout", "peerID", peerID) + utils.GetLogInstance().Warn("[SYNC] SendNewBlockToUnsync to peer timeout", "peerID", peerID) // send last time and delete config.client.PushNewBlock(selfPeerID, blockHash, true) node.stateMutex.Lock() diff --git a/node/node_handler.go b/node/node_handler.go index 4dbf075d2..93a002cfc 100644 --- a/node/node_handler.go +++ b/node/node_handler.go @@ -15,6 +15,7 @@ import ( proto_node "github.com/harmony-one/harmony/api/proto/node" "github.com/harmony-one/harmony/core/types" "github.com/harmony-one/harmony/crypto/pki" + "github.com/harmony-one/harmony/internal/utils" "github.com/harmony-one/harmony/p2p" "github.com/harmony-one/harmony/p2p/host" ) @@ -40,7 +41,7 @@ func (node *Node) StreamHandler(s p2p.Stream) { content, err := p2p.ReadMessageContent(s) if err != nil { - node.log.Error("Read p2p data failed", "err", err, "node", node) + utils.GetLogInstance().Error("Read p2p data failed", "err", err, "node", node) return } node.MaybeBroadcastAsValidator(content) @@ -49,19 +50,19 @@ func (node *Node) StreamHandler(s p2p.Stream) { msgCategory, err := proto.GetMessageCategory(content) if err != nil { - node.log.Error("Read node type failed", "err", err, "node", node) + utils.GetLogInstance().Error("Read node type failed", "err", err, "node", node) return } msgType, err := proto.GetMessageType(content) if err != nil { - node.log.Error("Read action type failed", "err", err, "node", node) + utils.GetLogInstance().Error("Read action type failed", "err", err, "node", node) return } msgPayload, err := proto.GetMessagePayload(content) if err != nil { - node.log.Error("Read message payload failed", "err", err, "node", node) + utils.GetLogInstance().Error("Read message payload failed", "err", err, "node", node) return } @@ -74,18 +75,18 @@ func (node *Node) StreamHandler(s p2p.Stream) { switch messageType { case proto_identity.Register: fmt.Println("received a identity message") - node.log.Info("NET: received message: IDENTITY/REGISTER") + utils.GetLogInstance().Info("NET: received message: IDENTITY/REGISTER") default: - node.log.Error("Announce message should be sent to IdentityChain") + utils.GetLogInstance().Error("Announce message should be sent to IdentityChain") } } case proto.Consensus: msgPayload, _ := proto.GetConsensusMessagePayload(content) if consensusObj.IsLeader { - node.log.Info("NET: Leader received message:", "messageCategory", msgCategory, "messageType", msgType) + utils.GetLogInstance().Info("NET: Leader received message:", "messageCategory", msgCategory, "messageType", msgType) consensusObj.ProcessMessageLeader(msgPayload) } else { - node.log.Info("NET: Validator received message:", "messageCategory", msgCategory, "messageType", msgType) + utils.GetLogInstance().Info("NET: Validator received message:", "messageCategory", msgCategory, "messageType", msgType) consensusObj.ProcessMessageValidator(msgPayload) // TODO(minhdoan): add logic to check if the current blockchain is not sync with other consensus // we should switch to other state rather than DoingConsensus. @@ -94,17 +95,17 @@ func (node *Node) StreamHandler(s p2p.Stream) { actionType := proto_node.MessageType(msgType) switch actionType { case proto_node.Transaction: - node.log.Info("NET: received message: Node/Transaction") + utils.GetLogInstance().Info("NET: received message: Node/Transaction") node.transactionMessageHandler(msgPayload) case proto_node.Block: - node.log.Info("NET: received message: Node/Block") + utils.GetLogInstance().Info("NET: received message: Node/Block") blockMsgType := proto_node.BlockMessageType(msgPayload[0]) switch blockMsgType { case proto_node.Sync: var blocks []*types.Block err := rlp.DecodeBytes(msgPayload[1:], &blocks) // skip the Sync messge type if err != nil { - node.log.Error("block sync", "error", err) + utils.GetLogInstance().Error("block sync", "error", err) } else { if node.Client != nil && node.Client.UpdateBlocks != nil && blocks != nil { node.Client.UpdateBlocks(blocks) @@ -112,10 +113,10 @@ func (node *Node) StreamHandler(s p2p.Stream) { } } case proto_node.Control: - node.log.Info("NET: received message: Node/Control") + utils.GetLogInstance().Info("NET: received message: Node/Control") controlType := msgPayload[0] if proto_node.ControlMessageType(controlType) == proto_node.STOP { - node.log.Debug("Stopping Node", "node", node, "numBlocks", node.blockchain.CurrentBlock().NumberU64(), "numTxsProcessed", node.countNumTransactionsInBlockchain()) + utils.GetLogInstance().Debug("Stopping Node", "node", node, "numBlocks", node.blockchain.CurrentBlock().NumberU64(), "numTxsProcessed", node.countNumTransactionsInBlockchain()) var avgBlockSizeInBytes common.StorageSize txCount := 0 @@ -135,7 +136,7 @@ func (node *Node) StreamHandler(s p2p.Stream) { avgTxSize = avgTxSize / txCount } - node.log.Debug("Blockchain Report", "totalNumBlocks", blockCount, "avgBlockSizeInCurrentEpoch", avgBlockSizeInBytes, "totalNumTxs", txCount, "avgTxSzieInCurrentEpoch", avgTxSize) + utils.GetLogInstance().Debug("Blockchain Report", "totalNumBlocks", blockCount, "avgBlockSizeInCurrentEpoch", avgBlockSizeInBytes, "totalNumTxs", txCount, "avgTxSzieInCurrentEpoch", avgTxSize) os.Exit(0) } @@ -145,7 +146,7 @@ func (node *Node) StreamHandler(s p2p.Stream) { node.pongMessageHandler(msgPayload) } default: - node.log.Error("Unknown", "MsgCategory", msgCategory) + utils.GetLogInstance().Error("Unknown", "MsgCategory", msgCategory) } } @@ -157,7 +158,7 @@ func (node *Node) transactionMessageHandler(msgPayload []byte) { txs := types.Transactions{} err := rlp.Decode(bytes.NewReader(msgPayload[1:]), &txs) // skip the Send messge type if err != nil { - node.log.Error("Failed to deserialize transaction list", "error", err) + utils.GetLogInstance().Error("Failed to deserialize transaction list", "error", err) } node.addPendingTransactions(txs) @@ -187,7 +188,7 @@ func (node *Node) transactionMessageHandler(msgPayload []byte) { // WaitForConsensusReady listen for the readiness signal from consensus and generate new block for consensus. func (node *Node) WaitForConsensusReady(readySignal chan struct{}) { - node.log.Debug("Waiting for Consensus ready", "node", node) + utils.GetLogInstance().Debug("Waiting for Consensus ready", "node", node) time.Sleep(15 * time.Second) // Wait for other nodes to be ready (test-only) firstTime := true @@ -201,7 +202,7 @@ func (node *Node) WaitForConsensusReady(readySignal chan struct{}) { case <-time.After(200 * time.Second): node.Consensus.ResetState() timeoutCount++ - node.log.Debug("Consensus timeout, retry!", "count", timeoutCount, "node", node) + utils.GetLogInstance().Debug("Consensus timeout, retry!", "count", timeoutCount, "node", node) } for { @@ -211,7 +212,7 @@ func (node *Node) WaitForConsensusReady(readySignal chan struct{}) { threshold = 2 firstTime = false } - node.log.Debug("STARTING BLOCK", "threshold", threshold, "pendingTransactions", len(node.pendingTransactions)) + utils.GetLogInstance().Debug("STARTING BLOCK", "threshold", threshold, "pendingTransactions", len(node.pendingTransactions)) if len(node.pendingTransactions) >= threshold { // Normal tx block consensus selectedTxs := node.getTransactionsForNewBlock(MaxNumberOfTransactionsPerBlock) @@ -219,7 +220,7 @@ func (node *Node) WaitForConsensusReady(readySignal chan struct{}) { node.Worker.CommitTransactions(selectedTxs) block, err := node.Worker.Commit() if err != nil { - node.log.Debug("Failed commiting new block", "Error", err) + utils.GetLogInstance().Debug("Failed commiting new block", "Error", err) } else { newBlock = block break @@ -242,7 +243,7 @@ func (node *Node) WaitForConsensusReady(readySignal chan struct{}) { // TODO (lc): broadcast the new blocks to new nodes doing state sync func (node *Node) BroadcastNewBlock(newBlock *types.Block) { if node.ClientPeer != nil { - node.log.Debug("Sending new block to client", "client", node.ClientPeer) + utils.GetLogInstance().Debug("Sending new block to client", "client", node.ClientPeer) node.SendMessage(*node.ClientPeer, proto_node.ConstructBlocksSyncMessage([]*types.Block{newBlock})) } } @@ -251,13 +252,13 @@ func (node *Node) BroadcastNewBlock(newBlock *types.Block) { func (node *Node) VerifyNewBlock(newBlock *types.Block) bool { err := node.blockchain.ValidateNewBlock(newBlock, pki.GetAddressFromPublicKey(node.SelfPeer.PubKey)) if err != nil { - node.log.Debug("Failed verifying new block", "Error", err, "tx", newBlock.Transactions()[0]) + utils.GetLogInstance().Debug("Failed verifying new block", "Error", err, "tx", newBlock.Transactions()[0]) // send consensus block to state syncing select { case node.Consensus.ConsensusBlock <- newBlock: default: - node.log.Warn("consensus block unable to sent to state sync", "height", newBlock.NumberU64(), "blockHash", newBlock.Hash().Hex()) + utils.GetLogInstance().Warn("consensus block unable to sent to state sync", "height", newBlock.NumberU64(), "blockHash", newBlock.Hash().Hex()) } return false @@ -281,19 +282,19 @@ func (node *Node) PostConsensusProcessing(newBlock *types.Block) { func (node *Node) AddNewBlock(newBlock *types.Block) { blockNum, err := node.blockchain.InsertChain([]*types.Block{newBlock}) if err != nil { - node.log.Debug("Error adding new block to blockchain", "blockNum", blockNum, "Error", err) + utils.GetLogInstance().Debug("Error adding new block to blockchain", "blockNum", blockNum, "Error", err) } else { - node.log.Info("adding new block to blockchain", "blockNum", blockNum) + utils.GetLogInstance().Info("adding new block to blockchain", "blockNum", blockNum) } } func (node *Node) pingMessageHandler(msgPayload []byte) int { ping, err := proto_node.GetPingMessage(msgPayload) if err != nil { - node.log.Error("Can't get Ping Message") + utils.GetLogInstance().Error("Can't get Ping Message") return -1 } - // node.log.Info("Ping", "Msg", ping) + // utils.GetLogInstance().Info("Ping", "Msg", ping) peer := new(p2p.Peer) peer.IP = ping.Node.IP @@ -304,12 +305,12 @@ func (node *Node) pingMessageHandler(msgPayload []byte) int { peer.PubKey = &bls.PublicKey{} err = peer.PubKey.Deserialize(ping.Node.PubKey[:]) if err != nil { - node.log.Error("UnmarshalBinary Failed", "error", err) + utils.GetLogInstance().Error("UnmarshalBinary Failed", "error", err) return -1 } if ping.Node.Role == proto_node.ClientRole { - node.log.Info("Add Client Peer to Node", "Node", node.Consensus.GetNodeID(), "Client", peer) + utils.GetLogInstance().Info("Add Client Peer to Node", "Node", node.Consensus.GetNodeID(), "Client", peer) node.ClientPeer = peer return 0 } @@ -341,11 +342,11 @@ func (node *Node) pingMessageHandler(msgPayload []byte) int { func (node *Node) pongMessageHandler(msgPayload []byte) int { pong, err := proto_node.GetPongMessage(msgPayload) if err != nil { - node.log.Error("Can't get Pong Message") + utils.GetLogInstance().Error("Can't get Pong Message") return -1 } - // node.log.Debug("pongMessageHandler", "pong", pong, "nodeID", node.Consensus.GetNodeID()) + // utils.GetLogInstance().Debug("pongMessageHandler", "pong", pong, "nodeID", node.Consensus.GetNodeID()) peers := make([]*p2p.Peer, 0) @@ -359,7 +360,7 @@ func (node *Node) pongMessageHandler(msgPayload []byte) int { peer.PubKey = &bls.PublicKey{} err = peer.PubKey.Deserialize(p.PubKey[:]) if err != nil { - node.log.Error("UnmarshalBinary Failed", "error", err) + utils.GetLogInstance().Error("UnmarshalBinary Failed", "error", err) continue } peers = append(peers, peer) @@ -379,7 +380,7 @@ func (node *Node) pongMessageHandler(msgPayload []byte) int { key := bls.PublicKey{} err = key.Deserialize(k[:]) if err != nil { - node.log.Error("UnmarshalBinary Failed PubKeys", "error", err) + utils.GetLogInstance().Error("UnmarshalBinary Failed PubKeys", "error", err) continue } publicKeys = append(publicKeys, &key) diff --git a/scripts/go_executable_build.sh b/scripts/go_executable_build.sh index 8113d6195..f3ddde73d 100755 --- a/scripts/go_executable_build.sh +++ b/scripts/go_executable_build.sh @@ -12,7 +12,20 @@ GOOS=linux GOARCH=amd64 FOLDER=/${WHOAMI:-$USER} RACE= -source ~/.bash_profile + +export CGO_CFLAGS="-I$PWD/../bls/include -I$PWD/../mcl/include" +export CGO_LDFLAGS="-L$PWD/../bls/lib" +export LD_LIBRARY_PATH=$PWD/../bls/lib:$PWD/../mcl/lib + +OS=$(uname -s) +case $OS in + Darwin) + export CGO_CFLAGS="-I$PWD/../bls/include -I$PWD/../mcl/include -I/usr/local/opt/openssl/include" + export CGO_LDFLAGS="-L$PWD/../bls/lib -L/usr/local/opt/openssl/lib" + export LD_LIBRARY_PATH=$PWD/../bls/lib:$PWD/../mcl/lib:/usr/local/opt/openssl/lib + export DYLD_LIBRARY_PATH=$LD_LIBRARY_PATH + ;; +esac if [ "$(uname -s)" == "Darwin" ]; then MD5='md5 -r' diff --git a/scripts/travis_checker.sh b/scripts/travis_checker.sh index e92086292..cbfb53345 100755 --- a/scripts/travis_checker.sh +++ b/scripts/travis_checker.sh @@ -36,7 +36,20 @@ dirnames() { go_dirs="${tmpdir}/go_dirs.txt" dirnames < "${go_files}" | sort -u -t/ > "${go_dirs}" -source ~/.bash_profile + +export CGO_CFLAGS="-I$PWD/../bls/include -I$PWD/../mcl/include" +export CGO_LDFLAGS="-L$PWD/../bls/lib" +export LD_LIBRARY_PATH=$PWD/../bls/lib:$PWD/../mcl/lib + +OS=$(uname -s) +case $OS in + Darwin) + export CGO_CFLAGS="-I$PWD/../bls/include -I$PWD/../mcl/include -I/usr/local/opt/openssl/include" + export CGO_LDFLAGS="-L$PWD/../bls/lib -L/usr/local/opt/openssl/lib" + export LD_LIBRARY_PATH=$PWD/../bls/lib:$PWD/../mcl/lib:/usr/local/opt/openssl/lib + export DYLD_LIBRARY_PATH=$LD_LIBRARY_PATH + ;; +esac echo "Running go test..." if go test -v -count=1 ./... diff --git a/test/deploy.sh b/test/deploy.sh index b99368c86..2109dfa1b 100755 --- a/test/deploy.sh +++ b/test/deploy.sh @@ -2,7 +2,20 @@ ROOT=$(dirname $0)/.. USER=$(whoami) -source ~/.bash_profile + +export CGO_CFLAGS="-I$PWD/../bls/include -I$PWD/../mcl/include" +export CGO_LDFLAGS="-L$PWD/../bls/lib" +export LD_LIBRARY_PATH=$PWD/../bls/lib:$PWD/../mcl/lib + +OS=$(uname -s) +case $OS in + Darwin) + export CGO_CFLAGS="-I$PWD/../bls/include -I$PWD/../mcl/include -I/usr/local/opt/openssl/include" + export CGO_LDFLAGS="-L$PWD/../bls/lib -L/usr/local/opt/openssl/lib" + export LD_LIBRARY_PATH=$PWD/../bls/lib:$PWD/../mcl/lib:/usr/local/opt/openssl/lib + export DYLD_LIBRARY_PATH=$LD_LIBRARY_PATH + ;; +esac set -x set -eo pipefail