diff --git a/app/client/cli/debug.go b/app/client/cli/debug.go index e873882dc..b7f2fc0d7 100644 --- a/app/client/cli/debug.go +++ b/app/client/cli/debug.go @@ -1,10 +1,10 @@ package cli import ( - "log" "os" "github.com/manifoldco/promptui" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/p2p" debugABP "github.com/pokt-network/pocket/p2p/providers/addrbook_provider/debug" debugCHP "github.com/pokt-network/pocket/p2p/providers/current_height_provider/debug" @@ -77,7 +77,7 @@ func NewDebugCommand() *cobra.Command { // TODO(#429): refactor injecting the dependencies into the bus so that they can be consumed in an updated `P2PModule.Create()` implementation p2pM, err := p2p.CreateWithProviders(runtimeMgr.GetBus(), debugAddressBookProvider, debugCurrentHeightProvider) if err != nil { - log.Fatalf("[ERROR] Failed to create p2p module: %v", err.Error()) + logger.Global.Fatal().Err(err).Msg("Failed to create p2p module") } p2pMod = p2pM.(modules.P2PModule) @@ -111,7 +111,7 @@ func promptGetInput() (string, error) { } if err != nil { - log.Printf("Prompt failed %v\n", err) + logger.Global.Error().Err(err).Msg("Prompt failed") return "", err } @@ -151,7 +151,7 @@ func handleSelect(selection string) { } sendDebugMessage(m) default: - log.Println("Selection not yet implemented...", selection) + logger.Global.Error().Msg("Selection not yet implemented...") } } @@ -159,7 +159,7 @@ func handleSelect(selection string) { func broadcastDebugMessage(debugMsg *messaging.DebugMessage) { anyProto, err := anypb.New(debugMsg) if err != nil { - log.Fatalf("[ERROR] Failed to create Any proto: %v", err) + logger.Global.Fatal().Err(err).Msg("Failed to create Any proto") } // TODO(olshansky): Once we implement the cleanup layer in RainTree, we'll be able to use @@ -170,7 +170,7 @@ func broadcastDebugMessage(debugMsg *messaging.DebugMessage) { for _, valAddr := range validators { addr, err := pocketCrypto.NewAddress(valAddr.GetAddress()) if err != nil { - log.Fatalf("[ERROR] Failed to convert validator address into pocketCrypto.Address: %v", err) + logger.Global.Fatal().Err(err).Msg("Failed to convert validator address into pocketCrypto.Address") } p2pMod.Send(addr, anyProto) } @@ -180,18 +180,18 @@ func broadcastDebugMessage(debugMsg *messaging.DebugMessage) { func sendDebugMessage(debugMsg *messaging.DebugMessage) { anyProto, err := anypb.New(debugMsg) if err != nil { - log.Fatalf("[ERROR] Failed to create Any proto: %v", err) + logger.Global.Error().Err(err).Msg("Failed to create Any proto") } var validatorAddress []byte if len(validators) == 0 { - log.Fatalf("[ERROR] No validators found") + logger.Global.Fatal().Msg("No validators found") } // if the message needs to be broadcast, it'll be handled by the business logic of the message handler validatorAddress, err = pocketCrypto.NewAddress(validators[0].GetAddress()) if err != nil { - log.Fatalf("[ERROR] Failed to convert validator address into pocketCrypto.Address: %v", err) + logger.Global.Fatal().Err(err).Msg("Failed to convert validator address into pocketCrypto.Address") } p2pMod.Send(validatorAddress, anyProto) diff --git a/app/client/cli/docgen/main.go b/app/client/cli/docgen/main.go index 3ed197220..a98ffcfca 100644 --- a/app/client/cli/docgen/main.go +++ b/app/client/cli/docgen/main.go @@ -1,9 +1,8 @@ package main import ( - "log" - "github.com/pokt-network/pocket/app/client/cli" + "github.com/pokt-network/pocket/logger" "github.com/spf13/cobra/doc" ) @@ -12,6 +11,6 @@ func main() { cmd := cli.GetRootCmd() err := doc.GenMarkdownTree(cmd, "../doc/commands") if err != nil { - log.Fatal(err) + logger.Global.Fatal().Err(err).Msg("failed to generate markdown tree") } } diff --git a/app/client/cli/utils.go b/app/client/cli/utils.go index ec03639af..1ebd25ef2 100644 --- a/app/client/cli/utils.go +++ b/app/client/cli/utils.go @@ -7,13 +7,13 @@ import ( "encoding/hex" "fmt" "io" - "log" "math/big" "math/rand" "os" "strings" "time" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/rpc" "github.com/pokt-network/pocket/shared/codec" "github.com/pokt-network/pocket/shared/converters" @@ -61,7 +61,7 @@ func credentials(pwd string) string { } bytePassword, err := terminal.ReadPassword(int(os.Stdin.Fd())) if err != nil { - log.Fatalf(err.Error()) + logger.Global.Fatal().Err(err).Msg("failed to read password") } return strings.TrimSpace(string(bytePassword)) } diff --git a/app/client/doc/CHANGELOG.md b/app/client/doc/CHANGELOG.md index 331a7c16c..8c928ad7c 100644 --- a/app/client/doc/CHANGELOG.md +++ b/app/client/doc/CHANGELOG.md @@ -7,9 +7,13 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.0.0.7] - 2023-02-04 + +- Changed log lines to utilize new logger module. + ## [0.0.0.6] - 2023-02-02 -## Added +### Added - Fix broken link to `shared/crypto/README.md` in keybase documentation diff --git a/app/client/main.go b/app/client/main.go index bad39ccab..d23c4e0cf 100644 --- a/app/client/main.go +++ b/app/client/main.go @@ -2,24 +2,24 @@ package main import ( "context" - "log" "os" "os/signal" "syscall" "github.com/pokt-network/pocket/app/client/cli" + "github.com/pokt-network/pocket/logger" ) func main() { ctx := newCLIContext() err := cli.ExecuteContext(ctx) if ctx.Err() == context.Canceled || err == context.Canceled { - log.Fatalf("aborted\n") + logger.Global.Fatal().Msg("aborted") return } if err != nil { - log.Fatalf("err: %v\n", err) + logger.Global.Fatal().Err(err).Msg("failed to execute command") } } diff --git a/app/pocket/doc/CHANGELOG.md b/app/pocket/doc/CHANGELOG.md index 691fce55c..43a4a16ad 100644 --- a/app/pocket/doc/CHANGELOG.md +++ b/app/pocket/doc/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.0.0.2] - 2023-02-04 + +- Changed log lines to utilize new logger module. + ## [0.0.0.1] - 2023-01-10 - Updated module constructor to accept a `bus` and not a `runtimeMgr` anymore diff --git a/app/pocket/main.go b/app/pocket/main.go index 3d8a21e57..907b119a3 100644 --- a/app/pocket/main.go +++ b/app/pocket/main.go @@ -2,9 +2,9 @@ package main import ( "flag" - "log" "github.com/pokt-network/pocket/app" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/runtime" "github.com/pokt-network/pocket/shared" ) @@ -17,22 +17,22 @@ func main() { flag.Parse() if *v { - log.Printf("Version flag currently unused %s\n", app.AppVersion) + logger.Global.Info().Str("version", app.AppVersion).Msg("Version flag currently unused") return } runtimeMgr := runtime.NewManagerFromFiles(*configFilename, *genesisFilename) bus, err := runtime.CreateBus(runtimeMgr) if err != nil { - log.Fatalf("Failed to create bus: %s", err) + logger.Global.Fatal().Err(err).Msg("Failed to create bus") } pocketNode, err := shared.CreateNode(bus) if err != nil { - log.Fatalf("Failed to create pocket node: %s", err) + logger.Global.Fatal().Err(err).Msg("Failed to create pocket node") } if err = pocketNode.Start(); err != nil { - log.Fatalf("Failed to start pocket node: %s", err) + logger.Global.Fatal().Err(err).Msg("Failed to start pocket node") } } diff --git a/build/docs/CHANGELOG.md b/build/docs/CHANGELOG.md index b7a594e7e..653ffe29e 100644 --- a/build/docs/CHANGELOG.md +++ b/build/docs/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.0.0.7] - 2023-02-04 + +- Added `--decoration="none"` flag to `reflex` + ## [0.0.0.6] - 2023-01-23 - Added pprof feature flag guideline in docker-compose.yml diff --git a/build/scripts/watch.sh b/build/scripts/watch.sh index 26fe10a25..01d55d544 100755 --- a/build/scripts/watch.sh +++ b/build/scripts/watch.sh @@ -21,4 +21,5 @@ fi reflex \ --start-service \ -r '\.go' \ + --decoration="none" \ -s -- sh -c "$command"; diff --git a/build/scripts/watch_build.sh b/build/scripts/watch_build.sh index 89f72ccac..5f5e5b920 100755 --- a/build/scripts/watch_build.sh +++ b/build/scripts/watch_build.sh @@ -2,7 +2,7 @@ if command -v reflex >/dev/null then - reflex -r '\.go$' -s -- sh -c "go build -v app/pocket/main.go" + reflex -r '\.go$' -s --decoration="none" -- sh -c "go build -v app/pocket/main.go" else echo "reflex not found. Install with `go install github.com/cespare/reflex@latest`" fi diff --git a/consensus/block.go b/consensus/block.go index 71e21e317..ec7c37228 100644 --- a/consensus/block.go +++ b/consensus/block.go @@ -2,7 +2,6 @@ package consensus import ( "fmt" - "log" "unsafe" typesCons "github.com/pokt-network/pocket/consensus/types" @@ -14,11 +13,18 @@ func (m *consensusModule) commitBlock(block *coreTypes.Block) error { if err := m.utilityContext.Commit(block.BlockHeader.QuorumCertificate); err != nil { return err } - m.nodeLog(typesCons.CommittingBlock(m.height, len(block.Transactions))) + + m.logger.Info(). + Fields( + map[string]any{ + "height": block.BlockHeader.Height, + "transactions": len(block.Transactions), + }). + Msg("🧱🧱🧱 Committing block 🧱🧱🧱") // Release the context if err := m.utilityContext.Release(); err != nil { - log.Println("[WARN] Error releasing utility context: ", err) + m.logger.Warn().Err(err).Msg("Error releasing utility context") } m.utilityContext = nil @@ -36,7 +42,7 @@ func (m *consensusModule) isValidMessageBlock(msg *typesCons.HotstuffMessage) (b if step != NewRound { return false, fmt.Errorf("validateBlockBasic failed - block is nil during step %s", typesCons.StepToString[m.step]) } - m.nodeLog("[DEBUG] Nil (expected) block is present during NewRound step.") + m.logger.Debug().Msg("Nil (expected) block is present during NewRound step.") return true, nil } @@ -58,7 +64,7 @@ func (m *consensusModule) isValidMessageBlock(msg *typesCons.HotstuffMessage) (b // DISCUSS: The only difference between blocks from one step to another is the QC, so we need // to determine where/how to validate this if protoHash(m.block) != protoHash(block) { - log.Println("[TECHDEBT] validateBlockBasic warning - block hash is the same but serialization is not") + m.logger.Warn().Bool("TECHDEBT", true).Msg("WalidateBlockBasic warning - block hash is the same but serialization is not") } } @@ -70,9 +76,9 @@ func (m *consensusModule) refreshUtilityContext() error { // Catch-all structure to release the previous utility context if it wasn't properly cleaned up. // Ideally, this should not be called. if m.utilityContext != nil { - m.nodeLog(typesCons.NilUtilityContextWarning) + m.logger.Warn().Msg(typesCons.NilUtilityContextWarning) if err := m.utilityContext.Release(); err != nil { - log.Printf("[WARN] Error releasing utility context: %v\n", err) + m.logger.Warn().Err(err).Msg("Error releasing utility context") } m.utilityContext = nil } @@ -80,7 +86,7 @@ func (m *consensusModule) refreshUtilityContext() error { // Only one write context can exist at a time, and the utility context needs to instantiate // a new one to modify the state. if err := m.GetBus().GetPersistenceModule().ReleaseWriteContext(); err != nil { - log.Printf("[WARN] Error releasing persistence write context: %v\n", err) + m.logger.Warn().Err(err).Msg("Error releasing persistence write context") } utilityContext, err := m.GetBus().GetUtilityModule().NewContext(int64(m.height)) diff --git a/consensus/debugging.go b/consensus/debugging.go index 10c8020ec..21de8fad5 100644 --- a/consensus/debugging.go +++ b/consensus/debugging.go @@ -1,8 +1,6 @@ package consensus import ( - "log" - typesCons "github.com/pokt-network/pocket/consensus/types" "github.com/pokt-network/pocket/shared/messaging" ) @@ -21,7 +19,7 @@ func (m *consensusModule) HandleDebugMessage(debugMessage *messaging.DebugMessag case messaging.DebugMessageAction_DEBUG_CONSENSUS_TOGGLE_PACE_MAKER_MODE: m.togglePacemakerManualMode(debugMessage) default: - log.Printf("Debug message: %s \n", debugMessage.Message) + m.logger.Debug().Msgf("Debug message: %s", debugMessage.Message) } return nil } @@ -43,7 +41,7 @@ func (m *consensusModule) GetNodeState() typesCons.ConsensusNodeState { } func (m *consensusModule) resetToGenesis(_ *messaging.DebugMessage) { - m.nodeLog(typesCons.DebugResetToGenesis) + m.logger.Debug().Msg(typesCons.DebugResetToGenesis) m.height = 0 m.ResetForNewHeight() @@ -58,11 +56,16 @@ func (m *consensusModule) resetToGenesis(_ *messaging.DebugMessage) { func (m *consensusModule) printNodeState(_ *messaging.DebugMessage) { state := m.GetNodeState() - m.nodeLog(typesCons.DebugNodeState(state)) + m.logger.Debug(). + Fields(map[string]any{ + "step": state.Step, + "height": state.Height, + "round": state.Round, + }).Msg("Node state") } func (m *consensusModule) triggerNextView(_ *messaging.DebugMessage) { - m.nodeLog(typesCons.DebugTriggerNextView) + m.logger.Debug().Msg(typesCons.DebugTriggerNextView) currentHeight := m.height currentStep := m.step @@ -80,9 +83,9 @@ func (m *consensusModule) triggerNextView(_ *messaging.DebugMessage) { func (m *consensusModule) togglePacemakerManualMode(_ *messaging.DebugMessage) { newMode := !m.paceMaker.IsManualMode() if newMode { - m.nodeLog(typesCons.DebugTogglePacemakerManualMode("MANUAL")) + m.logger.Debug().Str("pacemaker_mode", "MANUAL").Msg("Toggle pacemaker to MANUAL mode") } else { - m.nodeLog(typesCons.DebugTogglePacemakerManualMode("AUTOMATIC")) + m.logger.Debug().Str("pacemaker_mode", "AUTOMATIC").Msg("Toggle pacemaker to AUTOMATIC mode") } m.paceMaker.SetManualMode(newMode) } diff --git a/consensus/doc/CHANGELOG.md b/consensus/doc/CHANGELOG.md index e8ee102de..46dbec4ae 100644 --- a/consensus/doc/CHANGELOG.md +++ b/consensus/doc/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.0.0.25] - 2023-02-04 + +- Changed log lines to utilize new logger module. + ## [0.0.0.24] - 2023-02-03 - Introduced `hotstuffFIFOMempool` that extends the logic provided by the genericized FIFO mempool in `shared`. diff --git a/consensus/helpers.go b/consensus/helpers.go index 6521e49f9..7d0ee68a9 100644 --- a/consensus/helpers.go +++ b/consensus/helpers.go @@ -3,9 +3,9 @@ package consensus // TODO: Split this file into multiple helpers (e.g. signatures.go, hotstuff_helpers.go, etc...) import ( "encoding/base64" - "log" typesCons "github.com/pokt-network/pocket/consensus/types" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/shared/codec" coreTypes "github.com/pokt-network/pocket/shared/core/types" cryptoPocket "github.com/pokt-network/pocket/shared/crypto" @@ -29,9 +29,7 @@ const ( HotstuffMessageContentType = "consensus.HotstuffMessage" ) -var ( - HotstuffSteps = [...]typesCons.HotstuffStep{NewRound, Prepare, PreCommit, Commit, Decide} -) +var HotstuffSteps = [...]typesCons.HotstuffStep{NewRound, Prepare, PreCommit, Commit, Decide} // ** Hotstuff Helpers ** // @@ -45,17 +43,41 @@ func (m *consensusModule) getQuorumCertificate(height uint64, step typesCons.Hot return nil, err } if msg.GetPartialSignature() == nil { - m.nodeLog(typesCons.WarnMissingPartialSig(msg)) + + m.logger.Warn().Fields( + map[string]any{ + "height": msg.GetHeight(), + "step": msg.GetStep(), + "round": msg.GetRound(), + }, + ).Msg("No partial signature found which should not happen...") + continue } if msg.GetHeight() != height || msg.GetStep() != step || msg.GetRound() != round { - m.nodeLog(typesCons.WarnUnexpectedMessageInPool(msg, height, step, round)) + + m.logger.Warn().Fields( + map[string]any{ + "height": msg.GetHeight(), + "step": msg.GetStep(), + "round": msg.GetRound(), + }, + ).Msg("Message in pool does not match (height, step, round) of QC being generated") + continue } ps := msg.GetPartialSignature() if ps.Signature == nil || len(ps.Address) == 0 { - m.nodeLog(typesCons.WarnIncompletePartialSig(ps, msg)) + + m.logger.Warn().Fields( + map[string]any{ + "height": msg.GetHeight(), + "step": msg.GetStep(), + "round": msg.GetRound(), + }, + ).Msg("Partial signature is incomplete which should not happen...") + continue } pss = append(pss, msg.GetPartialSignature()) @@ -107,12 +129,12 @@ func getThresholdSignature(partialSigs []*typesCons.PartialSignature) (*typesCon func isSignatureValid(msg *typesCons.HotstuffMessage, pubKeyString string, signature []byte) bool { pubKey, err := cryptoPocket.NewPublicKey(pubKeyString) if err != nil { - log.Println("[WARN] Error getting PublicKey from bytes:", err) + logger.Global.Warn().Err(err).Msgf("Error getting PublicKey from bytes") return false } bytesToVerify, err := getSignableBytes(msg) if err != nil { - log.Println("[WARN] Error getting bytes to verify:", err) + logger.Global.Warn().Err(err).Msgf("Error getting bytes to verify") return false } return pubKey.Verify(bytesToVerify, signature) @@ -137,7 +159,7 @@ func (m *consensusModule) isOptimisticThresholdMet(numSignatures int, validators func protoHash(m proto.Message) string { b, err := codec.GetCodec().Marshal(m) if err != nil { - log.Fatalf("Could not marshal proto message: %v", err) + logger.Global.Fatal().Err(err).Msg("Could not marshal proto message") } return base64.StdEncoding.EncodeToString(b) } @@ -145,29 +167,36 @@ func protoHash(m proto.Message) string { /*** P2P Helpers ***/ func (m *consensusModule) sendToLeader(msg *typesCons.HotstuffMessage) { - m.nodeLog(typesCons.SendingMessage(msg, *m.leaderId)) + m.logger.Info().Fields( + map[string]any{ + "node_id": m.leaderId, + "height": msg.GetHeight(), + "step": msg.GetStep(), + "round": msg.GetRound(), + }, + ).Msg("✉️ Sending message ✉️") // TODO: This can happen due to a race condition with the pacemaker. if m.leaderId == nil { - m.nodeLogError(typesCons.ErrNilLeaderId.Error(), nil) + m.logger.Error().Msg(typesCons.ErrNilLeaderId.Error()) return } anyConsensusMessage, err := codec.GetCodec().ToAny(msg) if err != nil { - m.nodeLogError(typesCons.ErrCreateConsensusMessage.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCreateConsensusMessage.Error()) return } validators, err := m.getValidatorsAtHeight(m.CurrentHeight()) if err != nil { - m.nodeLogError(typesCons.ErrPersistenceGetAllValidators.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrPersistenceGetAllValidators.Error()) } idToValAddrMap := typesCons.NewActorMapper(validators).GetIdToValAddrMap() if err := m.GetBus().GetP2PModule().Send(cryptoPocket.AddressFromString(idToValAddrMap[*m.leaderId]), anyConsensusMessage); err != nil { - m.nodeLogError(typesCons.ErrSendMessage.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrSendMessage.Error()) return } } @@ -175,22 +204,28 @@ func (m *consensusModule) sendToLeader(msg *typesCons.HotstuffMessage) { // Star-like (O(n)) broadcast - send to all nodes directly // INVESTIGATE: Re-evaluate if we should be using our structured broadcast (RainTree O(log3(n))) algorithm instead func (m *consensusModule) broadcastToValidators(msg *typesCons.HotstuffMessage) { - m.nodeLog(typesCons.BroadcastingMessage(msg)) + m.logger.Info().Fields( + map[string]any{ + "height": m.CurrentHeight(), + "step": m.step, + "round": m.round, + }, + ).Msg("📣 Broadcasting message 📣") anyConsensusMessage, err := codec.GetCodec().ToAny(msg) if err != nil { - m.nodeLogError(typesCons.ErrCreateConsensusMessage.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCreateConsensusMessage.Error()) return } validators, err := m.getValidatorsAtHeight(m.CurrentHeight()) if err != nil { - m.nodeLogError(typesCons.ErrPersistenceGetAllValidators.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrPersistenceGetAllValidators.Error()) } for _, val := range validators { if err := m.GetBus().GetP2PModule().Send(cryptoPocket.AddressFromString(val.GetAddress()), anyConsensusMessage); err != nil { - m.nodeLogError(typesCons.ErrBroadcastMessage.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrBroadcastMessage.Error()) } } } @@ -223,7 +258,15 @@ func (m *consensusModule) clearLeader() { func (m *consensusModule) electNextLeader(message *typesCons.HotstuffMessage) error { leaderId, err := m.leaderElectionMod.ElectNextLeader(message) if err != nil || leaderId == 0 { - m.nodeLogError(typesCons.ErrLeaderElection(message).Error(), err) + + m.logger.Error().Err(err).Fields( + map[string]any{ + "leaderId": leaderId, + "height": m.height, + "round": m.round, + }, + ).Msg("leader election failed: Validator cannot take part in consensus") + m.clearLeader() return err } @@ -238,10 +281,22 @@ func (m *consensusModule) electNextLeader(message *typesCons.HotstuffMessage) er if m.IsLeader() { m.setLogPrefix("LEADER") - m.nodeLog(typesCons.ElectedSelfAsNewLeader(idToValAddrMap[*m.leaderId], *m.leaderId, m.height, m.round)) + m.logger.Info().Fields( + map[string]any{ + "leaderId": idToValAddrMap[*m.leaderId], + "height": m.height, + "round": m.round, + }, + ).Msg("👑 I am the leader 👑") } else { m.setLogPrefix("REPLICA") - m.nodeLog(typesCons.ElectedNewLeader(idToValAddrMap[*m.leaderId], *m.leaderId, m.height, m.round)) + m.logger.Info().Fields( + map[string]any{ + "leaderId": idToValAddrMap[*m.leaderId], + "height": m.height, + "round": m.round, + }, + ).Msg("🙇 Elected leader 🙇") } return nil @@ -249,19 +304,12 @@ func (m *consensusModule) electNextLeader(message *typesCons.HotstuffMessage) er /*** General Infrastructure Helpers ***/ -// TODO(#164): Remove this once we have a proper logging system. -func (m *consensusModule) nodeLog(s string) { - log.Printf("[%s][%d] %s\n", m.logPrefix, m.nodeId, s) -} - -// TODO(#164): Remove this once we have a proper logging system. -func (m *consensusModule) nodeLogError(s string, err error) { - log.Printf("🐞[ERROR][%s][%d] %s: %v\n", m.logPrefix, m.nodeId, s, err) -} - func (m *consensusModule) setLogPrefix(logPrefix string) { - m.logPrefix = logPrefix - m.paceMaker.SetLogPrefix(logPrefix) + logger.Global.UpdateFields(map[string]any{ + "kind": logPrefix, + }) + // INVESTIGATE: Do we need to create a new logger here? + m.logger = logger.Global.CreateLoggerForModule("consensus") } func (m *consensusModule) getValidatorsAtHeight(height uint64) ([]*coreTypes.Actor, error) { diff --git a/consensus/hotstuff_handler.go b/consensus/hotstuff_handler.go index ef245b50a..0c829ee28 100644 --- a/consensus/hotstuff_handler.go +++ b/consensus/hotstuff_handler.go @@ -16,12 +16,22 @@ type HotstuffMessageHandler interface { func (m *consensusModule) handleHotstuffMessage(msg *typesCons.HotstuffMessage) error { step := msg.GetStep() - m.nodeLog(typesCons.DebugReceivedHandlingHotstuffMessage(msg)) + m.logger.Debug().Fields(map[string]any{ + "step": msg.GetStep(), + "height": msg.Height, + "round": msg.Round, + }).Msg("Received hotstuff msg") + // Pacemaker - Liveness & safety checks if shouldHandle, err := m.paceMaker.ShouldHandleMessage(msg); !shouldHandle { return err } - m.nodeLog(typesCons.DebugHandlingHotstuffMessage(msg)) + + m.logger.Debug().Fields(map[string]any{ + "step": msg.GetStep(), + "height": msg.Height, + "round": msg.Round, + }).Msg("Handling hotstuff msg") // Elect a leader for the current round if needed if m.shouldElectNextLeader() { diff --git a/consensus/hotstuff_leader.go b/consensus/hotstuff_leader.go index a5ce15b12..0ff364609 100644 --- a/consensus/hotstuff_leader.go +++ b/consensus/hotstuff_leader.go @@ -29,21 +29,28 @@ func (handler *HotstuffLeaderMessageHandler) HandleNewRoundMessage(m *consensusM handler.emitTelemetryEvent(m, msg) if err := handler.anteHandle(m, msg); err != nil { - m.nodeLogError(typesCons.ErrHotstuffValidation.Error(), err) + m.logger.Error().Msg(typesCons.ErrHotstuffValidation.Error()) return } // DISCUSS: Do we need to pause for `MinBlockFreqMSec` here to let more transactions or should we stick with optimistic responsiveness? if err := m.didReceiveEnoughMessageForStep(NewRound); err != nil { - m.nodeLog(typesCons.OptimisticVoteCountWaiting(NewRound, err.Error())) + m.logger.Info().Msg(typesCons.OptimisticVoteCountWaiting(NewRound, err.Error())) return } - m.nodeLog(typesCons.OptimisticVoteCountPassed(m.height, NewRound, m.round)) + + m.logger.Info().Fields( + map[string]any{ + "height": m.height, + "round": m.round, + "step": NewRound, + }, + ).Msg("📬 Received enough 📬 votes") // Clear the previous utility context, if it exists, and create a new one if err := m.refreshUtilityContext(); err != nil { - m.nodeLogError("Could not refresh utility context", err) + m.logger.Error().Err(err).Msg("Could not refresh utility context") return } @@ -57,7 +64,7 @@ func (handler *HotstuffLeaderMessageHandler) HandleNewRoundMessage(m *consensusM if m.shouldPrepareNewBlock(highPrepareQC) { block, err := m.prepareAndApplyBlock(highPrepareQC) if err != nil { - m.nodeLogError(typesCons.ErrPrepareBlock.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrPrepareBlock.Error()) m.paceMaker.InterruptRound("failed to prepare & apply block") return } @@ -66,7 +73,7 @@ func (handler *HotstuffLeaderMessageHandler) HandleNewRoundMessage(m *consensusM // Leader acts like a replica if `prepareQC` is not `nil` // TODO: Do we need to call `validateProposal` here similar to how replicas does it if err := m.applyBlock(highPrepareQC.Block); err != nil { - m.nodeLogError(typesCons.ErrApplyBlock.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrApplyBlock.Error()) m.paceMaker.InterruptRound("failed to apply block") return } @@ -78,7 +85,7 @@ func (handler *HotstuffLeaderMessageHandler) HandleNewRoundMessage(m *consensusM prepareProposeMessage, err := CreateProposeMessage(m.height, m.round, Prepare, m.block, highPrepareQC) if err != nil { - m.nodeLogError(typesCons.ErrCreateProposeMessage(Prepare).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCreateProposeMessage(Prepare).Error()) m.paceMaker.InterruptRound("failed to create propose message") return } @@ -87,7 +94,7 @@ func (handler *HotstuffLeaderMessageHandler) HandleNewRoundMessage(m *consensusM // Leader also acts like a replica prepareVoteMessage, err := CreateVoteMessage(m.height, m.round, Prepare, m.block, m.privateKey) if err != nil { - m.nodeLogError(typesCons.ErrCreateVoteMessage(Prepare).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCreateVoteMessage(Prepare).Error()) return } m.sendToLeader(prepareVoteMessage) @@ -100,19 +107,26 @@ func (handler *HotstuffLeaderMessageHandler) HandlePrepareMessage(m *consensusMo handler.emitTelemetryEvent(m, msg) if err := handler.anteHandle(m, msg); err != nil { - m.nodeLogError(typesCons.ErrHotstuffValidation.Error(), err) + m.logger.Error().Msg(typesCons.ErrHotstuffValidation.Error()) return } if err := m.didReceiveEnoughMessageForStep(Prepare); err != nil { - m.nodeLog(typesCons.OptimisticVoteCountWaiting(Prepare, err.Error())) + m.logger.Info().Msg(typesCons.OptimisticVoteCountWaiting(Prepare, err.Error())) return } - m.nodeLog(typesCons.OptimisticVoteCountPassed(m.height, Prepare, m.round)) + + m.logger.Info().Fields( + map[string]any{ + "height": m.height, + "round": m.round, + "step": Prepare, + }, + ).Msg("📬 Received enough 📬 votes") prepareQC, err := m.getQuorumCertificate(m.height, Prepare, m.round) if err != nil { - m.nodeLogError(typesCons.ErrQCInvalid(Prepare).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrQCInvalid(Prepare).Error()) return // TODO(olshansky): Should we interrupt the round here? } @@ -122,7 +136,7 @@ func (handler *HotstuffLeaderMessageHandler) HandlePrepareMessage(m *consensusMo preCommitProposeMessage, err := CreateProposeMessage(m.height, m.round, PreCommit, m.block, prepareQC) if err != nil { - m.nodeLogError(typesCons.ErrCreateProposeMessage(PreCommit).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCreateProposeMessage(PreCommit).Error()) m.paceMaker.InterruptRound("failed to create propose message") return } @@ -131,7 +145,7 @@ func (handler *HotstuffLeaderMessageHandler) HandlePrepareMessage(m *consensusMo // Leader also acts like a replica precommitVoteMessage, err := CreateVoteMessage(m.height, m.round, PreCommit, m.block, m.privateKey) if err != nil { - m.nodeLogError(typesCons.ErrCreateVoteMessage(PreCommit).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCreateVoteMessage(PreCommit).Error()) return } m.sendToLeader(precommitVoteMessage) @@ -144,19 +158,26 @@ func (handler *HotstuffLeaderMessageHandler) HandlePrecommitMessage(m *consensus handler.emitTelemetryEvent(m, msg) if err := handler.anteHandle(m, msg); err != nil { - m.nodeLogError(typesCons.ErrHotstuffValidation.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrHotstuffValidation.Error()) return } if err := m.didReceiveEnoughMessageForStep(PreCommit); err != nil { - m.nodeLog(typesCons.OptimisticVoteCountWaiting(PreCommit, err.Error())) + m.logger.Info().Msg(typesCons.OptimisticVoteCountWaiting(PreCommit, err.Error())) return } - m.nodeLog(typesCons.OptimisticVoteCountPassed(m.height, PreCommit, m.round)) + + m.logger.Info().Fields( + map[string]any{ + "height": m.height, + "round": m.round, + "step": PreCommit, + }, + ).Msg("📬 Received enough 📬 votes") preCommitQC, err := m.getQuorumCertificate(m.height, PreCommit, m.round) if err != nil { - m.nodeLogError(typesCons.ErrQCInvalid(PreCommit).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrQCInvalid(PreCommit).Error()) return // TODO(olshansky): Should we interrupt the round here? } @@ -166,7 +187,7 @@ func (handler *HotstuffLeaderMessageHandler) HandlePrecommitMessage(m *consensus commitProposeMessage, err := CreateProposeMessage(m.height, m.round, Commit, m.block, preCommitQC) if err != nil { - m.nodeLogError(typesCons.ErrCreateProposeMessage(Commit).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCreateProposeMessage(Commit).Error()) m.paceMaker.InterruptRound("failed to create propose message") return } @@ -175,7 +196,7 @@ func (handler *HotstuffLeaderMessageHandler) HandlePrecommitMessage(m *consensus // Leader also acts like a replica commitVoteMessage, err := CreateVoteMessage(m.height, m.round, Commit, m.block, m.privateKey) if err != nil { - m.nodeLogError(typesCons.ErrCreateVoteMessage(Commit).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCreateVoteMessage(Commit).Error()) return } m.sendToLeader(commitVoteMessage) @@ -188,19 +209,26 @@ func (handler *HotstuffLeaderMessageHandler) HandleCommitMessage(m *consensusMod handler.emitTelemetryEvent(m, msg) if err := handler.anteHandle(m, msg); err != nil { - m.nodeLogError(typesCons.ErrHotstuffValidation.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrHotstuffValidation.Error()) return } if err := m.didReceiveEnoughMessageForStep(Commit); err != nil { - m.nodeLog(typesCons.OptimisticVoteCountWaiting(Commit, err.Error())) + m.logger.Info().Msg(typesCons.OptimisticVoteCountWaiting(Commit, err.Error())) return } - m.nodeLog(typesCons.OptimisticVoteCountPassed(m.height, Commit, m.round)) + + m.logger.Info().Fields( + map[string]any{ + "height": m.height, + "round": m.round, + "step": Commit, + }, + ).Msg("📬 Received enough 📬 votes") commitQC, err := m.getQuorumCertificate(m.height, Commit, m.round) if err != nil { - m.nodeLogError(typesCons.ErrQCInvalid(Commit).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrQCInvalid(Commit).Error()) return // TODO(olshansky): Should we interrupt the round here? } @@ -209,14 +237,14 @@ func (handler *HotstuffLeaderMessageHandler) HandleCommitMessage(m *consensusMod decideProposeMessage, err := CreateProposeMessage(m.height, m.round, Decide, m.block, commitQC) if err != nil { - m.nodeLogError(typesCons.ErrCreateProposeMessage(Decide).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCreateProposeMessage(Decide).Error()) m.paceMaker.InterruptRound("failed to create propose message") return } m.broadcastToValidators(decideProposeMessage) if err := m.commitBlock(m.block); err != nil { - m.nodeLogError(typesCons.ErrCommitBlock.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCommitBlock.Error()) m.paceMaker.InterruptRound("failed to commit block") return } @@ -237,7 +265,7 @@ func (handler *HotstuffLeaderMessageHandler) HandleDecideMessage(m *consensusMod handler.emitTelemetryEvent(m, msg) if err := handler.anteHandle(m, msg); err != nil { - m.nodeLogError(typesCons.ErrHotstuffValidation.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrHotstuffValidation.Error()) return } } @@ -283,14 +311,14 @@ func (m *consensusModule) validateMessageSignature(msg *typesCons.HotstuffMessag if msg.GetStep() == NewRound { if partialSig != nil { - m.nodeLog(typesCons.ErrUnnecessaryPartialSigForNewRound.Error()) + m.logger.Error().Err(typesCons.ErrUnnecessaryPartialSigForNewRound) } return nil } if msg.GetType() == Propose { if partialSig != nil { - m.nodeLog(typesCons.ErrUnnecessaryPartialSigForLeaderProposal.Error()) + m.logger.Error().Err(typesCons.ErrUnnecessaryPartialSigForLeaderProposal) } return nil } @@ -334,7 +362,7 @@ func (m *consensusModule) validateMessageSignature(msg *typesCons.HotstuffMessag // Add proper tests and implementation once the mempool is implemented. func (m *consensusModule) indexHotstuffMessage(msg *typesCons.HotstuffMessage) error { if m.consCfg.MaxMempoolBytes < uint64(m.hotstuffMempool[typesCons.HotstuffStep(msg.Type)].TotalMsgBytes()) { - m.nodeLogError(typesCons.DisregardHotstuffMessage, typesCons.ErrConsensusMempoolFull) + m.logger.Error().Err(typesCons.ErrConsensusMempoolFull).Msg(typesCons.DisregardHotstuffMessage) return typesCons.ErrConsensusMempoolFull } @@ -399,13 +427,13 @@ func (m *consensusModule) prepareAndApplyBlock(qc *typesCons.QuorumCertificate) // ADDTEST: Add more tests for all the different scenarios here func (m *consensusModule) shouldPrepareNewBlock(highPrepareQC *typesCons.QuorumCertificate) bool { if highPrepareQC == nil { - m.nodeLog("Preparing a new block - no prepareQC found") + m.logger.Info().Msg("Preparing a new block - no prepareQC found") return true } else if m.isPrepareQCFromPast(highPrepareQC) { - m.nodeLog("Preparing a new block - prepareQC is from the past") + m.logger.Info().Msg("Preparing a new block - prepareQC is from the past") return true } else if highPrepareQC.Block == nil { - m.nodeLog("[WARN] Preparing a new block - prepareQC SHOULD be used but block is nil") + m.logger.Warn().Msg("Preparing a new block - prepareQC SHOULD be used but block is nil") return true } return false diff --git a/consensus/hotstuff_replica.go b/consensus/hotstuff_replica.go index 8495044f2..904342d49 100644 --- a/consensus/hotstuff_replica.go +++ b/consensus/hotstuff_replica.go @@ -1,8 +1,6 @@ package consensus import ( - "fmt" - consensusTelemetry "github.com/pokt-network/pocket/consensus/telemetry" "github.com/pokt-network/pocket/consensus/types" typesCons "github.com/pokt-network/pocket/consensus/types" @@ -31,13 +29,13 @@ func (handler *HotstuffReplicaMessageHandler) HandleNewRoundMessage(m *consensus handler.emitTelemetryEvent(m, msg) if err := handler.anteHandle(m, msg); err != nil { - m.nodeLogError(typesCons.ErrHotstuffValidation.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrHotstuffValidation.Error()) return } // Clear the previous utility context, if it exists, and create a new one if err := m.refreshUtilityContext(); err != nil { - m.nodeLogError("Could not refresh utility context", err) + m.logger.Error().Err(err).Msg("Could not refresh utility context") return } @@ -51,19 +49,19 @@ func (handler *HotstuffReplicaMessageHandler) HandlePrepareMessage(m *consensusM handler.emitTelemetryEvent(m, msg) if err := handler.anteHandle(m, msg); err != nil { - m.nodeLogError(typesCons.ErrHotstuffValidation.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrHotstuffValidation.Error()) return } if err := m.validateProposal(msg); err != nil { - m.nodeLogError(fmt.Sprintf("Invalid proposal in %s message", Prepare), err) + m.logger.Error().Err(err).Str("message", Prepare.String()).Msg("Invalid proposal") m.paceMaker.InterruptRound("invalid proposal") return } block := msg.GetBlock() if err := m.applyBlock(block); err != nil { - m.nodeLogError(typesCons.ErrApplyBlock.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrApplyBlock.Error()) m.paceMaker.InterruptRound("failed to apply block") return } @@ -72,7 +70,7 @@ func (handler *HotstuffReplicaMessageHandler) HandlePrepareMessage(m *consensusM prepareVoteMessage, err := CreateVoteMessage(m.height, m.round, Prepare, m.block, m.privateKey) if err != nil { - m.nodeLogError(typesCons.ErrCreateVoteMessage(Prepare).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCreateVoteMessage(Prepare).Error()) return // Not interrupting the round because liveness could continue with one failed vote } m.sendToLeader(prepareVoteMessage) @@ -85,13 +83,13 @@ func (handler *HotstuffReplicaMessageHandler) HandlePrecommitMessage(m *consensu handler.emitTelemetryEvent(m, msg) if err := handler.anteHandle(m, msg); err != nil { - m.nodeLogError(typesCons.ErrHotstuffValidation.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrHotstuffValidation.Error()) return } quorumCert := msg.GetQuorumCertificate() if err := m.validateQuorumCertificate(quorumCert); err != nil { - m.nodeLogError(typesCons.ErrQCInvalid(PreCommit).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrQCInvalid(PreCommit).Error()) m.paceMaker.InterruptRound("invalid quorum certificate") return } @@ -101,7 +99,7 @@ func (handler *HotstuffReplicaMessageHandler) HandlePrecommitMessage(m *consensu preCommitVoteMessage, err := CreateVoteMessage(m.height, m.round, PreCommit, m.block, m.privateKey) if err != nil { - m.nodeLogError(typesCons.ErrCreateVoteMessage(PreCommit).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCreateVoteMessage(PreCommit).Error()) return // Not interrupting the round because liveness could continue with one failed vote } m.sendToLeader(preCommitVoteMessage) @@ -114,13 +112,13 @@ func (handler *HotstuffReplicaMessageHandler) HandleCommitMessage(m *consensusMo handler.emitTelemetryEvent(m, msg) if err := handler.anteHandle(m, msg); err != nil { - m.nodeLogError(typesCons.ErrHotstuffValidation.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrHotstuffValidation.Error()) return } quorumCert := msg.GetQuorumCertificate() if err := m.validateQuorumCertificate(quorumCert); err != nil { - m.nodeLogError(typesCons.ErrQCInvalid(Commit).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrQCInvalid(Commit).Error()) m.paceMaker.InterruptRound("invalid quorum certificate") return } @@ -130,7 +128,7 @@ func (handler *HotstuffReplicaMessageHandler) HandleCommitMessage(m *consensusMo commitVoteMessage, err := CreateVoteMessage(m.height, m.round, Commit, m.block, m.privateKey) if err != nil { - m.nodeLogError(typesCons.ErrCreateVoteMessage(Commit).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrCreateVoteMessage(Commit).Error()) return // Not interrupting the round because liveness could continue with one failed vote } m.sendToLeader(commitVoteMessage) @@ -143,19 +141,19 @@ func (handler *HotstuffReplicaMessageHandler) HandleDecideMessage(m *consensusMo handler.emitTelemetryEvent(m, msg) if err := handler.anteHandle(m, msg); err != nil { - m.nodeLogError(typesCons.ErrHotstuffValidation.Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrHotstuffValidation.Error()) return } quorumCert := msg.GetQuorumCertificate() if err := m.validateQuorumCertificate(quorumCert); err != nil { - m.nodeLogError(typesCons.ErrQCInvalid(Decide).Error(), err) + m.logger.Error().Err(err).Msg(typesCons.ErrQCInvalid(Decide).Error()) m.paceMaker.InterruptRound("invalid quorum certificate") return } if err := m.commitBlock(m.block); err != nil { - m.nodeLogError("Could not commit block", err) + m.logger.Error().Err(err).Msg("Could not commit block") m.paceMaker.InterruptRound("failed to commit block") return } @@ -208,14 +206,14 @@ func (m *consensusModule) validateProposal(msg *typesCons.HotstuffMessage) error // Safety: not locked if lockedQC == nil { - m.nodeLog(typesCons.NotLockedOnQC) + m.logger.Info().Msg(typesCons.NotLockedOnQC) return nil } // Safety: check the hash of the locked QC // The equivalent of `lockedQC.Block.ExtendsFrom(justifyQC.Block)` in the hotstuff whitepaper is done in `applyBlock` below. if protoHash(lockedQC.GetBlock()) == protoHash(justifyQC.Block) { - m.nodeLog(typesCons.ProposalBlockExtends) + m.logger.Info().Msg(typesCons.ProposalBlockExtends) return nil } @@ -278,13 +276,16 @@ func (m *consensusModule) validateQuorumCertificate(qc *typesCons.QuorumCertific for _, partialSig := range qc.ThresholdSignature.Signatures { validator, ok := validatorMap[partialSig.Address] if !ok { - m.nodeLogError(typesCons.ErrMissingValidator(partialSig.Address, valAddrToIdMap[partialSig.Address]).Error(), nil) + m.logger.Error().Msgf(typesCons.ErrMissingValidator(partialSig.Address, valAddrToIdMap[partialSig.Address]).Error()) continue } // TODO(olshansky): Every call to `IsSignatureValid` does a serialization and should be optimized. We can // just serialize `Message` once and verify each signature without re-serializing every time. if !isSignatureValid(msgToJustify, validator.GetPublicKey(), partialSig.Signature) { - m.nodeLog(typesCons.WarnInvalidPartialSigInQC(partialSig.Address, valAddrToIdMap[partialSig.Address])) + m.logger.Warn().Fields(map[string]any{ + "address": partialSig.Address, + "nodeId": valAddrToIdMap[partialSig.Address], + }).Msg("QC contains an invalid partial signature") continue } numValid++ diff --git a/consensus/leader_election/module.go b/consensus/leader_election/module.go index 01f8d944e..745a6f7ed 100644 --- a/consensus/leader_election/module.go +++ b/consensus/leader_election/module.go @@ -1,9 +1,8 @@ package leader_election import ( - "log" - typesCons "github.com/pokt-network/pocket/consensus/types" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/shared/modules" ) @@ -47,7 +46,7 @@ func (m *leaderElectionModule) SetBus(pocketBus modules.Bus) { func (m *leaderElectionModule) GetBus() modules.Bus { if m.bus == nil { - log.Fatalf("PocketBus is not initialized") + logger.Global.Fatal().Msg("PocketBus is not initialized") } return m.bus } diff --git a/consensus/leader_election/sortition/sortition.go b/consensus/leader_election/sortition/sortition.go index f857a1dc0..cce12f224 100644 --- a/consensus/leader_election/sortition/sortition.go +++ b/consensus/leader_election/sortition/sortition.go @@ -11,13 +11,13 @@ Algorand's own implementation of the algorithm [2]. import ( crand "crypto/rand" "fmt" - "log" "math/big" "strings" "golang.org/x/exp/rand" "github.com/pokt-network/pocket/consensus/leader_election/vrf" + "github.com/pokt-network/pocket/logger" "gonum.org/v1/gonum/stat/distuv" ) @@ -41,7 +41,7 @@ func init() { var err error maxVrfOutFloat, base, err = big.ParseFloat(maxVrfOutFloatString, 0, vrfOutFloatPrecision, big.ToNearestEven) if base != 16 || err != nil { - log.Fatal("failed to parse big float constant for sortition") + logger.Global.Fatal().Msg("failed to parse big float constant for sortition") } maxRandomInt = big.NewInt(^int64(0)) @@ -70,7 +70,7 @@ func Sortition(validatorStake, networkStake, numExpectedCandidates uint64, vrfOu // Generate a random source using the crypto library f, err := crand.Int(crand.Reader, maxRandomInt) if err != nil { - log.Fatal("failed to generate random integer for sortition") + logger.Global.Fatal().Err(err).Msg("failed to generate random integer for sortition") } src := rand.NewSource(f.Uint64()) diff --git a/consensus/messages.go b/consensus/messages.go index e73e7443d..32513918e 100644 --- a/consensus/messages.go +++ b/consensus/messages.go @@ -1,9 +1,8 @@ package consensus import ( - "log" - typesCons "github.com/pokt-network/pocket/consensus/types" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/shared/codec" coreTypes "github.com/pokt-network/pocket/shared/core/types" "github.com/pokt-network/pocket/shared/crypto" @@ -80,13 +79,13 @@ func CreateVoteMessage( func getMessageSignature(msg *typesCons.HotstuffMessage, privKey crypto.PrivateKey) []byte { bytesToSign, err := getSignableBytes(msg) if err != nil { - log.Printf("[WARN] error getting bytes to sign: %v\n", err) + logger.Global.Warn().Err(err).Msgf("error getting bytes to sign") return nil } signature, err := privKey.Sign(bytesToSign) if err != nil { - log.Printf("[WARN] error signing message: %v\n", err) + logger.Global.Warn().Err(err).Msgf("error signing message") return nil } diff --git a/consensus/module.go b/consensus/module.go index 9acac4a30..66840432d 100644 --- a/consensus/module.go +++ b/consensus/module.go @@ -2,7 +2,6 @@ package consensus import ( "fmt" - "log" "sort" "sync" @@ -10,6 +9,7 @@ import ( "github.com/pokt-network/pocket/consensus/pacemaker" consensusTelemetry "github.com/pokt-network/pocket/consensus/telemetry" typesCons "github.com/pokt-network/pocket/consensus/types" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/runtime/configs" "github.com/pokt-network/pocket/runtime/genesis" "github.com/pokt-network/pocket/shared/codec" @@ -66,7 +66,7 @@ type consensusModule struct { paceMaker pacemaker.Pacemaker leaderElectionMod leader_election.LeaderElectionModule - // DEPRECATE: Remove later when we build a shared/proper/injected logger + logger modules.Logger logPrefix string hotstuffMempool map[typesCons.HotstuffStep]*hotstuffFIFOMempool @@ -194,6 +194,8 @@ func (m *consensusModule) Start() error { consensusTelemetry.CONSENSUS_BLOCKCHAIN_HEIGHT_COUNTER_DESCRIPTION, ) + m.logger = logger.Global.CreateLoggerForModule(m.GetModuleName()) + if err := m.loadPersistedState(); err != nil { return err } @@ -219,7 +221,7 @@ func (m *consensusModule) GetModuleName() string { func (m *consensusModule) GetBus() modules.Bus { if m.bus == nil { - log.Fatalf("PocketBus is not initialized") + logger.Global.Fatal().Msg("PocketBus is not initialized") } return m.bus } @@ -252,7 +254,7 @@ func (*consensusModule) ValidateGenesis(genesis *genesis.GenesisState) error { // There is an implicit dependency because of how RainTree works and how the validator map // is currently managed to make sure that the ordering of the address and the service URL // are the same. This will be addressed once the # of validators will scale. - panic("HACK(olshansky): service url and address must be sorted the same way") + logger.Global.Panic().Msg("HACK(olshansky): service url and address must be sorted the same way") } } @@ -315,7 +317,7 @@ func (m *consensusModule) loadPersistedState() error { m.height = uint64(latestHeight) + 1 // +1 because the height of the consensus module is where it is actively participating in consensus - m.nodeLog(fmt.Sprintf("Starting consensus module at height %d", latestHeight)) + m.logger.Info().Uint64("height", m.height).Msg("Starting consensus module") return nil } diff --git a/consensus/types/errors.go b/consensus/types/errors.go index 50ee82d10..7d7e88446 100644 --- a/consensus/types/errors.go +++ b/consensus/types/errors.go @@ -6,8 +6,8 @@ import ( "encoding/base64" "errors" "fmt" - "log" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/shared/codec" "google.golang.org/protobuf/proto" ) @@ -260,7 +260,7 @@ func ErrLeaderElection(msg *HotstuffMessage) error { func protoHash(m proto.Message) string { b, err := codec.GetCodec().Marshal(m) if err != nil { - log.Fatalf("Could not marshal proto message: %v", err) + logger.Global.Fatal().Err(err).Msg("Could not marshal proto message") } return base64.StdEncoding.EncodeToString(b) } diff --git a/consensus/types/types.go b/consensus/types/types.go index b12c85631..19517d3cd 100644 --- a/consensus/types/types.go +++ b/consensus/types/types.go @@ -7,9 +7,11 @@ import ( type NodeId uint64 -type ValAddrToIdMap map[string]NodeId // Mapping from hex encoded address to an integer node id. -type IdToValAddrMap map[NodeId]string // Mapping from node id to a hex encoded string address. -type ValidatorMap map[string]*coreTypes.Actor +type ( + ValAddrToIdMap map[string]NodeId // Mapping from hex encoded address to an integer node id. + IdToValAddrMap map[NodeId]string // Mapping from node id to a hex encoded string address. + ValidatorMap map[string]*coreTypes.Actor +) type ConsensusNodeState struct { NodeId NodeId diff --git a/logger/docs/CHANGELOG.md b/logger/docs/CHANGELOG.md index c35263c32..6d9000185 100644 --- a/logger/docs/CHANGELOG.md +++ b/logger/docs/CHANGELOG.md @@ -7,6 +7,12 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.0.0.3] - 2023-02-04 + +- Added readme +- Moved initialization of `Global` logger to `init` function +- Added `SetFields` and `UpdateFields` methods to `Logger` module + ## [0.0.0.2] - 2023-01-10 - Updated module constructor to accept a `bus` and not a `runtimeMgr` anymore diff --git a/logger/docs/README.md b/logger/docs/README.md new file mode 100644 index 000000000..bc90fcebc --- /dev/null +++ b/logger/docs/README.md @@ -0,0 +1,143 @@ +# Logger + +- [Configuration](#configuration) +- [Log Types](#log-types) + - [Levels](#levels) + - [Fields](#fields) + - [Int Field](#int-field) + - [String Field](#string-field) + - [Map Field](#map-field) +- [Global Logging](#global-logging) +- [Module Logging](#module-logging) + - [Logger Initialization](#logger-initialization) +- [Accessing Logs](#accessing-logs) + - [Grafana](#grafana) + - [Example Queries](#example-queries) + +## Configuration + +The logger module has the following configuration options found [here](./runtime/confg/../../../../runtime/configs/proto/logger_config.proto): + +```json +{ + "logger": { + "level": "debug", + "format": "pretty" + } +} +``` + +- `level`: log level; one of `debug`, `info`, `warn`, `error`, `fatal`, `panic` +- `format`: log format; one of `pretty`, `json` + +NOTE: Additional process wrapper ma change stdout output. For example, `reflex`, used for hot reloading, modifies the log lines. This can be avoided by using the `--decoration` flag. + +## Log Types + +### Levels + +The developer needs to provide the logging level for each log message: + +- Debug: `logger.Global.Logger.Debug().Msg(msg)` +- Error with `err`: `logger.Global.Logger.Error().Err(err).Msg(msg)` +- Error without `err`: `logger.Global.Logger.Error().Msg(msg)` +- Fatal:: `logger.Global.Fatal().Err(err).Msg(msg)` + +### Fields + +Metadata can, and should, be attached to each log level. Using the same key throughout makes the logs easier to parse. + +Refer to the [zerolog documentation](https://github.com/rs/zerolog#field-types) for more information on the available field types. + +#### Int Field + +For example, a single int field can be added like so: + +```golang +logger.Global.Logger.Debug().Uint64("height", height).Msg("Block committed") +``` + +#### String Field + +A single string field can be added like so: + +```golang +logger.Global.Logger.Debug().String("hash", hash).Msg("Block committed") +``` + +#### Map Field + +Multiple fields can be provided using a map: + +```golang +fields := map[string]interface{}{ + "height": height, + "hash": hash, +} + +logger.Global.Logger.Debug.Fields(fields).Msg("Block committed") +``` + +## Global Logging + +The global logger should be used when logging outside a module: + +```golang +import ( + ... + "github.com/pokt-network/pocket/logger" + ... +) + +func DoSomething() { + logger.Global.Fatal().Msg("Oops, something went wrong!") + ... +} +``` + +## Module Logging + +Each module should have its own logger to appropriately namespace the logs. + +```golang +type sweetModule struct { + logger modules.Logger +} + +func (m *sweetModule) DoSomething() { + m.logger.Fatal().Msg("Something is fishy!") + ... +} +``` + +### Logger Initialization + +`Global` logger is always available from the `logger` package. + +Each module has its own logger to provide an additional layer of granularity. +Please initiate loggers in the `Start` method of the module, like this: + +```golang +type sweetModule struct { + logger modules.Logger +} + +func (m *sweetModule) Start() error { + m.logger = logger.Global.CreateLoggerForModule(u.GetModuleName()) + ... +} +``` + +## Accessing Logs + +Logs are written to stdout. In LocalNet, Loki is used to capture log output. Logs can then be queried using [LogQL](https://grafana.com/docs/loki/latest/logql/) syntax. Grafana can be used to visualize the logs. + +### Grafana + +When running LocalNet via `make localnet_up`, Grafana can be accessed at [localhost:42000](https://localhost:42000). + +### Example Queries + +DOCUMENT: Add common query examples. + + diff --git a/logger/module.go b/logger/module.go index eba17509a..f3ce00f0a 100644 --- a/logger/module.go +++ b/logger/module.go @@ -1,6 +1,7 @@ package logger import ( + "fmt" "os" "strings" @@ -10,18 +11,17 @@ import ( ) type loggerModule struct { + zerolog.Logger bus modules.Bus logger modules.Logger config *configs.LoggerConfig } -// All loggers branch out of mainLogger, that way configuration changes to mainLogger propagate to others. -var mainLogger = zerolog.New(os.Stderr).With().Timestamp().Logger() +// Each module should have it's own logger to easily configure & filter logs by module. -// The idea is to create a logger for each module, so that we can easily filter logs by module. -// But we also need a global logger, because sometimes we need to log outside of modules, e.g. when the process just -// started, and modules are not initiated yet. -var Global = new(loggerModule).CreateLoggerForModule("global") +// A Global logger is also created to enable logging outside of modules (e.g. when the node is starting). +// All loggers branch out of Global, that way configuration changes to Global propagate to others. +var Global loggerModule var _ modules.LoggerModule = &loggerModule{} @@ -40,12 +40,20 @@ var pocketLogFormatToEnum = map[string]configs.LogFormat{ "pretty": configs.LogFormat_LOG_FORMAT_PRETTY, } +// init is called when the package is imported. +// It is used to initialize the global logger. +func init() { + Global = loggerModule{ + Logger: zerolog.New(os.Stdout).With().Timestamp().Logger(), + } +} + func Create(bus modules.Bus) (modules.Module, error) { return new(loggerModule).Create(bus) } func (*loggerModule) CreateLoggerForModule(moduleName string) modules.Logger { - return mainLogger.With().Str("module", moduleName).Logger() + return Global.Logger.With().Str("module", moduleName).Logger() } func (*loggerModule) Create(bus modules.Bus) (modules.Module, error) { @@ -56,24 +64,31 @@ func (*loggerModule) Create(bus modules.Bus) (modules.Module, error) { } bus.RegisterModule(m) - m.InitLogger() + Global.config = m.config + Global.CreateLoggerForModule("global") // Mapping config string value to the proto enum - if pocketLogLevel, ok := configs.LogLevel_value[`LogLevel_LOG_LEVEL_`+strings.ToUpper(m.config.Level)]; ok { + if pocketLogLevel, ok := configs.LogLevel_value[`LOG_LEVEL_`+strings.ToUpper(Global.config.GetLevel())]; ok { zerolog.SetGlobalLevel(pocketLogLevelToZeroLog[configs.LogLevel(pocketLogLevel)]) } else { zerolog.SetGlobalLevel(zerolog.NoLevel) } - if pocketLogFormatToEnum[m.config.Format] == configs.LogFormat_LOG_FORMAT_PRETTY { - mainLogger = mainLogger.Output(zerolog.ConsoleWriter{Out: os.Stderr}) - mainLogger.Info().Msg("using pretty log format") + if pocketLogFormatToEnum[Global.config.GetFormat()] == configs.LogFormat_LOG_FORMAT_PRETTY { + logStructure := zerolog.ConsoleWriter{Out: os.Stdout} + logStructure.FormatLevel = func(i interface{}) string { + return fmt.Sprintf("level=%s", strings.ToUpper(i.(string))) + } + + Global.Logger = Global.Logger.Output(logStructure) + Global.Logger.Info().Msg("using pretty log format") } - return m, nil + return &Global, nil } func (m *loggerModule) Start() error { + Global.Logger = m.CreateLoggerForModule("global") return nil } @@ -91,15 +106,27 @@ func (m *loggerModule) SetBus(bus modules.Bus) { func (m *loggerModule) GetBus() modules.Bus { if m.bus == nil { - m.logger.Fatal().Msg("Bus is not initialized") + m.Logger.Fatal().Msg("Bus is not initialized") } return m.bus } -func (m *loggerModule) InitLogger() { - m.logger = m.CreateLoggerForModule(m.GetModuleName()) +func (m *loggerModule) GetLogger() modules.Logger { + return m.Logger } -func (m *loggerModule) GetLogger() modules.Logger { - return m.logger +// INVESTIGATE(#420): https://github.com/pokt-network/pocket/issues/480 +// SetFields sets the fields for the global logger +func (m *loggerModule) SetFields(fields map[string]any) { + m.Logger = m.Logger.With().Fields(fields).Logger() +} + +// UpdateFields updates the fields for the global logger +func (m *loggerModule) UpdateFields(fields map[string]any) { + m.Logger.UpdateContext(func(c zerolog.Context) zerolog.Context { + for k, v := range fields { + c = c.Interface(k, v) + } + return c + }) } diff --git a/p2p/CHANGELOG.md b/p2p/CHANGELOG.md index 69bb978ce..e69d85c5b 100644 --- a/p2p/CHANGELOG.md +++ b/p2p/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.0.0.23] - 2023-02-04 + +- Changed log lines to utilize new logger module. + ## [0.0.0.22] - 2023-02-03 - Using the generic `mempool.GenericFIFOSet` as a `nonceDeduper` diff --git a/p2p/module.go b/p2p/module.go index e02868e1c..97d1be6dc 100644 --- a/p2p/module.go +++ b/p2p/module.go @@ -3,6 +3,7 @@ package p2p import ( "log" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/p2p/providers" persABP "github.com/pokt-network/pocket/p2p/providers/addrbook_provider/persistence" "github.com/pokt-network/pocket/p2p/raintree" @@ -25,6 +26,8 @@ type p2pModule struct { listener typesP2P.Transport address cryptoPocket.Address + logger modules.Logger + network typesP2P.Network injectedAddrBookProvider providers.AddrBookProvider @@ -98,7 +101,7 @@ func (m *p2pModule) SetBus(bus modules.Bus) { func (m *p2pModule) GetBus() modules.Bus { if m.bus == nil { - log.Printf("[WARN]: PocketBus is not initialized") + m.logger.Warn().Msg("PocketBus is not initialized") return nil } return m.bus @@ -109,7 +112,7 @@ func (m *p2pModule) GetModuleName() string { } func (m *p2pModule) Start() error { - log.Println("Starting network module") + logger.Global.Info().Msg("Starting network module") addrbookProvider := getAddrBookProvider(m) currentHeightProvider := getCurrentHeightProvider(m) @@ -138,7 +141,7 @@ func (m *p2pModule) Start() error { for { data, err := m.listener.Read() if err != nil { - log.Println("Error reading data from connection: ", err) + m.logger.Error().Err(err).Msg("Error reading data from connection") continue } go m.handleNetworkMessage(data) @@ -176,7 +179,7 @@ func getCurrentHeightProvider(m *p2pModule) providers.CurrentHeightProvider { } func (m *p2pModule) Stop() error { - log.Println("Stopping network module") + m.logger.Info().Msg("Stopping network module") if err := m.listener.Close(); err != nil { return err } @@ -191,7 +194,7 @@ func (m *p2pModule) Broadcast(msg *anypb.Any) error { if err != nil { return err } - log.Println("broadcasting message to network") + m.logger.Info().Msg("broadcasting message to network") return m.network.NetworkBroadcast(data) } @@ -216,7 +219,7 @@ func (m *p2pModule) GetAddress() (cryptoPocket.Address, error) { func (m *p2pModule) handleNetworkMessage(networkMsgData []byte) { appMsgData, err := m.network.HandleNetworkData(networkMsgData) if err != nil { - log.Println("Error handling raw data: ", err) + m.logger.Error().Err(err).Msg("Error handling raw data") return } @@ -229,7 +232,7 @@ func (m *p2pModule) handleNetworkMessage(networkMsgData []byte) { networkMessage := messaging.PocketEnvelope{} if err := proto.Unmarshal(appMsgData, &networkMessage); err != nil { - log.Println("Error decoding network message: ", err) + m.logger.Error().Err(err).Msg("Error decoding network message") return } diff --git a/p2p/module_raintree_test.go b/p2p/module_raintree_test.go index 0fdcd81a6..ba8a75a4f 100644 --- a/p2p/module_raintree_test.go +++ b/p2p/module_raintree_test.go @@ -33,7 +33,7 @@ func TestMain(m *testing.M) { func TestRainTreeNetworkCompleteOneNodes(t *testing.T) { // val_1 originatorNode := validatorId(1) - var expectedCalls = TestNetworkSimulationConfig{ + expectedCalls := TestNetworkSimulationConfig{ originatorNode: {0, 0}, // val_1, the originator, does 0 network reads or writes } testRainTreeCalls(t, originatorNode, expectedCalls) @@ -47,7 +47,7 @@ func TestRainTreeNetworkCompleteTwoNodes(t *testing.T) { // Per the diagram above, in the case of a 2 node network, the originator node (val_1) does a // single write to another node (val_2), also the // originator node and never performs any reads or writes during a RainTree broadcast. - var expectedCalls = TestNetworkSimulationConfig{ + expectedCalls := TestNetworkSimulationConfig{ // Attempt: I think Validator 1 is sending a message in a 2 (including self) node network originatorNode: {0, 1}, // val_1 does a single network write (to val_2) validatorId(2): {1, 0}, // val_2 does a single network read (from val_1) @@ -60,7 +60,7 @@ func TestRainTreeNetworkCompleteThreeNodes(t *testing.T) { // ┌───────┴────┬─────────┐ // val_2 val_1 val_3 originatorNode := validatorId(1) - var expectedCalls = TestNetworkSimulationConfig{ + expectedCalls := TestNetworkSimulationConfig{ originatorNode: {0, 2}, // val_1 does two network writes (to val_2 and val_3) validatorId(2): {1, 0}, // val_2 does a single network read (from val_1) validatorId(3): {1, 0}, // val_2 does a single network read (from val_3) @@ -76,7 +76,7 @@ func TestRainTreeNetworkCompleteFourNodes(t *testing.T) { // └───────┐ └───────┐ └───────┐ // val_3 val_2 val_4 originatorNode := validatorId(1) - var expectedCalls = TestNetworkSimulationConfig{ + expectedCalls := TestNetworkSimulationConfig{ originatorNode: {0, 3}, // val_1 does 3 network writes (two to val_2 and 1 to val_3) validatorId(2): {2, 1}, // val_2 does 2 network reads (both from val_1) and 1 network write (to val_3) validatorId(3): {2, 1}, // val_2 does 2 network reads (from val_1 and val_2) and 1 network write (to val_4) @@ -92,7 +92,7 @@ func TestRainTreeNetworkCompleteNineNodes(t *testing.T) { // ┌───────┴────┬─────────┐ ┌───────┴────┬─────────┐ ┌───────┴────┬─────────┐ // val_6 val_4 val_8 val_3 val_1 val_5 val_9 val_7 val_2 originatorNode := validatorId(1) - var expectedCalls = TestNetworkSimulationConfig{ + expectedCalls := TestNetworkSimulationConfig{ originatorNode: {0, 4}, validatorId(2): {1, 0}, validatorId(3): {1, 0}, @@ -116,7 +116,7 @@ func TestRainTreeNetworkCompleteNineNodes(t *testing.T) { func TestRainTreeCompleteTwelveNodes(t *testing.T) { originatorNode := validatorId(1) - var expectedCalls = TestNetworkSimulationConfig{ + expectedCalls := TestNetworkSimulationConfig{ originatorNode: {1, 6}, validatorId(2): {3, 2}, validatorId(3): {2, 2}, @@ -142,7 +142,7 @@ func TestRainTreeNetworkCompleteEighteenNodes(t *testing.T) { // ┌────────┴─────┬───────────┐ ┌───────┴────┬──────────┐ ┌────────┴─────┬──────────┐ ┌───────┴────┬──────────┐ ┌───────┴────┬─────────┐ ┌────────┴────┬─────────┐ ┌───────┴─────┬──────────┐ ┌────────┴─────┬───────────┐ ┌───────┴────┬──────────┐ // val_13 val_11 val_16 val_9 val_7 val_12 val_17 val_15 val_8 val_7 val_5 val_10 val_3 val_1 val_6 val_11 val_9 val_2 val_1 val_17 val_4 val_15 val_13 val_18 val_5 val_3 val_14 originatorNode := validatorId(1) - var expectedCalls = TestNetworkSimulationConfig{ + expectedCalls := TestNetworkSimulationConfig{ originatorNode: {1, 6}, validatorId(2): {1, 0}, validatorId(3): {2, 2}, @@ -174,7 +174,7 @@ func TestRainTreeNetworkCompleteTwentySevenNodes(t *testing.T) { // ┌────────┴─────┬───────────┐ ┌────────┴─────┬───────────┐ ┌────────┴─────┬───────────┐ ┌────────┴────┬──────────┐ ┌───────┴────┬─────────┐ ┌────────┴─────┬──────────┐ ┌───────┴─────┬──────────┐ ┌────────┴─────┬───────────┐ ┌───────┴────┬──────────┐ // val_20 val_16 val_24 val_14 val_10 val_18 val_26 val_22 val_12 val_11 val_7 val_15 val_5 val_1 val_9 val_17 val_13 val_3 val_2 val_25 val_6 val_23 val_19 val_27 val_8 val_4 val_21 originatorNode := validatorId(1) - var expectedCalls = TestNetworkSimulationConfig{ + expectedCalls := TestNetworkSimulationConfig{ originatorNode: {0, 6}, validatorId(2): {1, 0}, validatorId(3): {1, 0}, diff --git a/p2p/raintree/addrbook_utils.go b/p2p/raintree/addrbook_utils.go index 042a0edc8..55109a8ac 100644 --- a/p2p/raintree/addrbook_utils.go +++ b/p2p/raintree/addrbook_utils.go @@ -1,9 +1,7 @@ package raintree import ( - "log" "math" - "strings" ) // Refer to the P2P specification for a formal description and proof of how the constants are selected @@ -22,7 +20,7 @@ func (n *rainTreeNetwork) getAddrBookLength(level uint32, height uint64) int { if height < n.GetBus().GetConsensusModule().CurrentHeight() { peersManagerWithAddrBookProvider, err := newPeersManagerWithAddrBookProvider(n.selfAddr, n.addrBookProvider, height) if err != nil { - log.Fatalf("[ERROR] Error initializing rainTreeNetwork peersManagerWithAddrBookProvider: %v", err) + n.logger.Fatal().Err(err).Msg("Error initializing rainTreeNetwork peersManagerWithAddrBookProvider") } peersManagerStateView = peersManagerWithAddrBookProvider.getNetworkView() } @@ -38,7 +36,13 @@ func (n *rainTreeNetwork) getTargetsAtLevel(level uint32) []target { firstTarget := n.getTarget(firstMsgTargetPercentage, addrBookLengthAtHeight, level) secondTarget := n.getTarget(secondMsgTargetPercentage, addrBookLengthAtHeight, level) - log.Printf("[DEBUG] Targets at height (%d): %s", level, n.debugMsgTargetString(firstTarget, secondTarget)) + n.logger.Debug().Fields( + map[string]any{ + "firstTarget": firstTarget, + "secondTarget": secondTarget, + "height": height, + }, + ).Msg("Targets at height") return []target{firstTarget, secondTarget} } @@ -68,15 +72,8 @@ func (n *rainTreeNetwork) getTarget(targetPercentage float64, addrBookLen int, l target.address = addr.Address return target } - log.Printf("[DEBUG] addrStr %s not found in addrBookMap", addrStr) - return target -} -// Only used for debug logging to understand what RainTree is doing under the hood -func (n *rainTreeNetwork) debugMsgTargetString(target1, target2 target) string { - s := strings.Builder{} - s.WriteString(target1.DebugString(n)) - s.WriteString(" --|-- ") - s.WriteString(target2.DebugString(n)) - return s.String() + n.logger.Debug().Str("addrStr", addrStr).Msg("addrStr not found in addrBookMap") + + return target } diff --git a/p2p/raintree/network.go b/p2p/raintree/network.go index e69eddfdd..c75a63161 100644 --- a/p2p/raintree/network.go +++ b/p2p/raintree/network.go @@ -6,6 +6,7 @@ import ( "math/rand" "time" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/p2p/providers" "github.com/pokt-network/pocket/p2p/providers/addrbook_provider" typesP2P "github.com/pokt-network/pocket/p2p/types" @@ -18,8 +19,10 @@ import ( "google.golang.org/protobuf/proto" ) -var _ typesP2P.Network = &rainTreeNetwork{} -var _ modules.IntegratableModule = &rainTreeNetwork{} +var ( + _ typesP2P.Network = &rainTreeNetwork{} + _ modules.IntegratableModule = &rainTreeNetwork{} +) type rainTreeNetwork struct { bus modules.Bus @@ -29,17 +32,19 @@ type rainTreeNetwork struct { peersManager *peersManager nonceDeduper *mempool.GenericFIFOSet[uint64, uint64] + + logger modules.Logger } func NewRainTreeNetwork(addr cryptoPocket.Address, bus modules.Bus, addrBookProvider providers.AddrBookProvider, currentHeightProvider providers.CurrentHeightProvider) typesP2P.Network { addrBook, err := addrBookProvider.GetStakedAddrBookAtHeight(currentHeightProvider.CurrentHeight()) if err != nil { - log.Fatalf("[ERROR] Error getting addrBook: %v", err) + logger.Global.Fatal().Err(err).Msg("Error getting addrBook") } pm, err := newPeersManager(addr, addrBook, true) if err != nil { - log.Fatalf("[ERROR] Error initializing rainTreeNetwork peersManager: %v", err) + logger.Global.Fatal().Err(err).Msg("Error initializing rainTreeNetwork peersManager") } p2pCfg := bus.GetRuntimeMgr().GetConfig().P2P @@ -76,13 +81,13 @@ func (n *rainTreeNetwork) networkBroadcastAtLevel(data []byte, level uint32, non for _, target := range n.getTargetsAtLevel(level) { if shouldSendToTarget(target) { if err = n.networkSendInternal(msgBz, target.address); err != nil { - log.Println("Error sending to peer during broadcast: ", err) + n.logger.Error().Err(err).Msg("Error sending to peer during broadcast") } } } if err = n.demote(msg); err != nil { - log.Println("Error demoting self during RainTree message propagation: ", err) + n.logger.Error().Err(err).Msg("Error demoting self during RainTree message propagation") } return nil @@ -120,11 +125,11 @@ func (n *rainTreeNetwork) networkSendInternal(data []byte, address cryptoPocket. peer, ok := n.peersManager.getNetworkView().addrBookMap[address.String()] if !ok { - return fmt.Errorf("address %s not found in addrBookMap", address.String()) + n.logger.Error().Str("address", address.String()).Msg("address not found in addrBookMap") } if err := peer.Dialer.Write(data); err != nil { - log.Println("Error writing to peer during send: ", err) + n.logger.Error().Err(err).Msg("Error writing to peer during send") return err } @@ -166,7 +171,7 @@ func (n *rainTreeNetwork) HandleNetworkData(data []byte) ([]byte, error) { networkMessage := messaging.PocketEnvelope{} if err := proto.Unmarshal(rainTreeMsg.Data, &networkMessage); err != nil { - log.Println("Error decoding network message: ", err) + n.logger.Error().Err(err).Msg("Error decoding network message") return nil, err } diff --git a/p2p/raintree/peers_manager.go b/p2p/raintree/peers_manager.go index 9ee686f5c..2a0aafcd3 100644 --- a/p2p/raintree/peers_manager.go +++ b/p2p/raintree/peers_manager.go @@ -1,11 +1,11 @@ package raintree import ( - "log" "math" "sort" "sync" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/p2p/providers/addrbook_provider" typesP2P "github.com/pokt-network/pocket/p2p/types" cryptoPocket "github.com/pokt-network/pocket/shared/crypto" @@ -66,7 +66,10 @@ func newPeersManager(selfAddr cryptoPocket.Address, addrBook typesP2P.AddrBook, i := sort.SearchStrings(pm.addrList, pm.selfAddr.String()) if i == len(pm.addrList) { - log.Printf("[⚠️ client-only mode]: self address not found for %s in addrBook so this client can send messages but does not propagate them", pm.selfAddr) + logger.Global.Warn(). + Str("address", pm.selfAddr.String()). + Str("mode", "client-only"). + Msg("self address not found in addrBook so this client can send messages but does not propagate them") } // The list is sorted lexicographically above, but is reformatted below so this addr of this node // is always the first in the list. This makes RainTree propagation easier to compute and interpret. diff --git a/p2p/stdnetwork/network.go b/p2p/stdnetwork/network.go index bb589cb01..d696e1563 100644 --- a/p2p/stdnetwork/network.go +++ b/p2p/stdnetwork/network.go @@ -4,25 +4,29 @@ package stdnetwork import ( "fmt" - "log" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/p2p/providers" typesP2P "github.com/pokt-network/pocket/p2p/types" cryptoPocket "github.com/pokt-network/pocket/shared/crypto" "github.com/pokt-network/pocket/shared/modules" ) -var _ typesP2P.Network = &network{} -var _ modules.IntegratableModule = &network{} +var ( + _ typesP2P.Network = &network{} + _ modules.IntegratableModule = &network{} +) type network struct { addrBookMap typesP2P.AddrBookMap + + logger modules.Logger } func NewNetwork(bus modules.Bus, addrBookProvider providers.AddrBookProvider, currentHeightProvider providers.CurrentHeightProvider) (n typesP2P.Network) { addrBook, err := addrBookProvider.GetStakedAddrBookAtHeight(currentHeightProvider.CurrentHeight()) if err != nil { - log.Fatalf("[ERROR] Error getting addrBook: %v", err) + logger.Global.Fatal().Err(err).Msg("Error getting addrBook") } addrBookMap := make(typesP2P.AddrBookMap) @@ -30,6 +34,7 @@ func NewNetwork(bus modules.Bus, addrBookProvider providers.AddrBookProvider, cu addrBookMap[peer.Address.String()] = peer } return &network{ + logger: bus.GetLoggerModule().CreateLoggerForModule("network"), addrBookMap: addrBookMap, } } @@ -38,7 +43,7 @@ func NewNetwork(bus modules.Bus, addrBookProvider providers.AddrBookProvider, cu func (n *network) NetworkBroadcast(data []byte) error { for _, peer := range n.addrBookMap { if err := peer.Dialer.Write(data); err != nil { - log.Println("Error writing to one of the peers during broadcast: ", err) + n.logger.Error().Err(err).Msg("Error writing to one of the peers during broadcast") continue } } @@ -52,7 +57,7 @@ func (n *network) NetworkSend(data []byte, address cryptoPocket.Address) error { } if err := peer.Dialer.Write(data); err != nil { - log.Println("Error writing to peer during send: ", err) + n.logger.Error().Err(err).Msg("Error writing to peer during send") return err } diff --git a/p2p/utils_test.go b/p2p/utils_test.go index 4fa9994e8..f340ae060 100644 --- a/p2p/utils_test.go +++ b/p2p/utils_test.go @@ -159,7 +159,7 @@ func createMockBus(t *testing.T, runtimeMgr modules.RuntimeMgr) *mockModules.Moc // createMockGenesisState configures and returns a mocked GenesisState func createMockGenesisState(t *testing.T, valKeys []cryptoPocket.PrivateKey) *genesis.GenesisState { - var genesisState = new(genesis.GenesisState) + genesisState := new(genesis.GenesisState) validators := make([]*coreTypes.Actor, len(valKeys)) for i, valKey := range valKeys { diff --git a/persistence/context.go b/persistence/context.go index 0cba31df8..e0343229a 100644 --- a/persistence/context.go +++ b/persistence/context.go @@ -4,7 +4,6 @@ package persistence import ( "context" - "log" "github.com/jackc/pgx/v5" "github.com/pokt-network/pocket/persistence/indexer" @@ -22,6 +21,8 @@ type PostgresContext struct { stateHash string + logger modules.Logger + // TECHDEBT(#361): These three values are pointers to objects maintained by the PersistenceModule. // Need to simply access them via the bus. blockStore kvstore.KVStore @@ -30,13 +31,13 @@ type PostgresContext struct { } func (p PostgresContext) NewSavePoint(bytes []byte) error { - log.Println("TODO: NewSavePoint not implemented") + p.logger.Info().Bool("TODO", true).Msg("NewSavePoint not implemented") return nil } // TECHDEBT(#327): Guarantee atomicity betweens `prepareBlock`, `insertBlock` and `storeBlock` for save points & rollbacks. func (p PostgresContext) RollbackToSavePoint(bytes []byte) error { - log.Println("TODO: RollbackToSavePoint not fully implemented") + p.logger.Info().Bool("TODO", true).Msg("RollbackToSavePoint not fully implemented") return p.getTx().Rollback(context.TODO()) } @@ -53,7 +54,7 @@ func (p *PostgresContext) ComputeStateHash() (string, error) { // TECHDEBT(#327): Make sure these operations are atomic func (p PostgresContext) Commit(proposerAddr, quorumCert []byte) error { - log.Printf("About to commit block & context at height %d.\n", p.Height) + p.logger.Info().Int64("height", p.Height).Msg("About to commit block & context") // Create a persistence block proto block, err := p.prepareBlock(proposerAddr, quorumCert) @@ -77,14 +78,14 @@ func (p PostgresContext) Commit(proposerAddr, quorumCert []byte) error { return err } if err := p.conn.Close(ctx); err != nil { - log.Println("[TODO][ERROR] Implement connection pooling. Error when closing DB connecting...", err) + p.logger.Error().Err(err).Bool("TODO", true).Msg("Error when closing DB connection") } return nil } func (p PostgresContext) Release() error { - log.Printf("About to release postgres context at height %d.\n", p.Height) + p.logger.Info().Int64("height", p.Height).Msg("About to release context") ctx := context.TODO() if err := p.getTx().Rollback(ctx); err != nil { return err @@ -96,7 +97,7 @@ func (p PostgresContext) Release() error { } func (p PostgresContext) Close() error { - log.Printf("About to close postgres context at height %d.\n", p.Height) + p.logger.Info().Int64("height", p.Height).Msg("About to close postgres context") return p.conn.Close(context.TODO()) } diff --git a/persistence/db.go b/persistence/db.go index bdeb1f26d..c6b1860de 100644 --- a/persistence/db.go +++ b/persistence/db.go @@ -4,7 +4,6 @@ import ( "context" "errors" "fmt" - "log" "time" "github.com/jackc/pgconn" @@ -61,7 +60,7 @@ func (pg *PostgresContext) ResetContext() error { } if !conn.IsClosed() { if err := pg.Release(); err != nil { - log.Println("[TODO][ERROR] Error releasing write context...", err) + pg.logger.Error().Err(err).Bool("TODO", true).Msg("error releasing write context") } } pg.tx = nil diff --git a/persistence/debug.go b/persistence/debug.go index 3c1ef9238..30fdac495 100644 --- a/persistence/debug.go +++ b/persistence/debug.go @@ -2,7 +2,6 @@ package persistence import ( "crypto/sha256" - "log" "runtime/debug" "github.com/celestiaorg/smt" @@ -38,7 +37,7 @@ func (m *persistenceModule) HandleDebugMessage(debugMessage *messaging.DebugMess g := m.genesisState m.populateGenesisState(g) // fatal if there's an error default: - log.Printf("Debug message not handled by persistence module: %s \n", debugMessage.Message) + m.logger.Debug().Str("message", debugMessage.Message.String()).Msg("Debug message not handled by persistence module") } return nil } @@ -48,17 +47,17 @@ func (m *persistenceModule) showLatestBlockInStore(_ *messaging.DebugMessage) { height := m.GetBus().GetConsensusModule().CurrentHeight() - 1 blockBytes, err := m.GetBlockStore().Get(heightToBytes(int64(height))) if err != nil { - log.Printf("Error getting block %d from block store: %s \n", height, err) + m.logger.Error().Err(err).Uint64("height", height).Msg("Error getting block from block store") return } block := &coreTypes.Block{} if err := codec.GetCodec().Unmarshal(blockBytes, block); err != nil { - log.Printf("Error decoding block %d from block store: %s \n", height, err) + m.logger.Error().Err(err).Uint64("height", height).Msg("Error decoding block from block store") return } - log.Printf("Block at height %d: %+v \n", height, block) + m.logger.Info().Uint64("height", height).Str("block", block.String()).Msg("Block from block store") } // TECHDEBT: Make sure this is atomic @@ -89,7 +88,7 @@ func (m *persistenceModule) clearAllState(_ *messaging.DebugMessage) error { return err } - log.Println("Cleared all the state") + m.logger.Info().Msg("Cleared all the state") // reclaming memory manually because the above calls deallocate and reallocate a lot of memory debug.FreeOSMemory() return nil diff --git a/persistence/docs/CHANGELOG.md b/persistence/docs/CHANGELOG.md index 18b007530..57bdc2be5 100644 --- a/persistence/docs/CHANGELOG.md +++ b/persistence/docs/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.0.0.30] - 2023-02-04 + +- Changed log lines to utilize new logger module. + ## [0.0.0.29] - 2023-01-31 - Use hash of serialised protobufs for keys in `updateParamsTree()` and `updateFlagsTree()` diff --git a/persistence/genesis.go b/persistence/genesis.go index 3716b3432..214eee52b 100644 --- a/persistence/genesis.go +++ b/persistence/genesis.go @@ -13,7 +13,7 @@ import ( // CONSIDERATION: Should this return an error and let the caller decide if it should log a fatal error? func (m *persistenceModule) populateGenesisState(state *genesis.GenesisState) { - log.Println("Populating genesis state...") + m.logger.Info().Msg("Populating genesis state...") // REFACTOR: This business logic should probably live in `types/genesis.go` // and we need to add proper unit tests for it.` @@ -32,23 +32,23 @@ func (m *persistenceModule) populateGenesisState(state *genesis.GenesisState) { rwContext, err := m.NewRWContext(0) if err != nil { - log.Fatalf("an error occurred creating the rwContext for the genesis state: %s", err.Error()) + m.logger.Fatal().Err(err).Msg("an error occurred creating the rwContext for the genesis state") } for _, acc := range state.GetAccounts() { addrBz, err := hex.DecodeString(acc.GetAddress()) if err != nil { - log.Fatalf("an error occurred converting address to bytes %s", acc.GetAddress()) + m.logger.Fatal().Err(err).Str("address", acc.GetAddress()).Msg("an error occurred converting address to bytes") } err = rwContext.SetAccountAmount(addrBz, acc.GetAmount()) if err != nil { - log.Fatalf("an error occurred inserting an acc in the genesis state: %s", err.Error()) + m.logger.Fatal().Err(err).Str("address", acc.GetAddress()).Msg("an error occurred inserting an acc in the genesis state") } } for _, pool := range state.GetPools() { err = rwContext.InsertPool(pool.GetAddress(), pool.GetAmount()) // pool.GetAddress() returns the pool's semantic name if err != nil { - log.Fatalf("an error occurred inserting an pool in the genesis state: %s", err.Error()) + m.logger.Fatal().Err(err).Str("address", pool.GetAddress()).Msg("an error occurred inserting an pool in the genesis state") } } @@ -115,20 +115,20 @@ func (m *persistenceModule) populateGenesisState(state *genesis.GenesisState) { } if err = rwContext.InitFlags(); err != nil { // TODO (Team) use flags from genesis file not hardcoded - log.Fatalf("an error occurred initializing flags: %s", err.Error()) + m.logger.Fatal().Err(err).Msg("an error occurred initializing flags") } // Updates all the merkle trees stateHash, err := rwContext.ComputeStateHash() if err != nil { - log.Fatalf("an error occurred updating the app hash during genesis: %s", err.Error()) + m.logger.Fatal().Err(err).Msg("an error occurred updating the app hash during genesis") } - log.Println("PopulateGenesisState - computed state hash:", stateHash) + m.logger.Info().Str("stateHash", stateHash).Msg("PopulateGenesisState - computed state hash") // This updates the DB, blockstore, and commits the genesis state. // Note that the `quorumCert for genesis` is nil. if err = rwContext.Commit(nil, nil); err != nil { - log.Fatalf("error committing genesis state to DB %s ", err.Error()) + m.logger.Fatal().Err(err).Msg("an error occurred committing the genesis state to the DB") } } diff --git a/persistence/gov.go b/persistence/gov.go index fd8923f48..c7e7d8161 100644 --- a/persistence/gov.go +++ b/persistence/gov.go @@ -3,7 +3,6 @@ package persistence import ( "encoding/hex" "fmt" - "log" "reflect" "strconv" "strings" @@ -176,7 +175,7 @@ func getParamOrFlag[T int | string | []byte](p PostgresContext, tableName, param return any(v).(T), enabled, err default: - log.Fatalf("unhandled type for paramValue %T", tp) + p.logger.Fatal().Msgf("unhandled type for paramValue %T", tp) } return } diff --git a/persistence/indexer/indexer_test.go b/persistence/indexer/indexer_test.go index a15b2dc87..5bec05ee3 100644 --- a/persistence/indexer/indexer_test.go +++ b/persistence/indexer/indexer_test.go @@ -218,9 +218,7 @@ const ( UnjailMessage ) -var ( - msgTypes = []MessageType{SendMessage, StakeMessage, UnstakeMessage, EditStakeMessage, UnjailMessage} -) +var msgTypes = []MessageType{SendMessage, StakeMessage, UnstakeMessage, EditStakeMessage, UnjailMessage} func (mt MessageType) String() string { switch mt { diff --git a/persistence/kvstore/kvstore.go b/persistence/kvstore/kvstore.go index f0a2d7976..660b43fd7 100644 --- a/persistence/kvstore/kvstore.go +++ b/persistence/kvstore/kvstore.go @@ -26,8 +26,10 @@ const ( BadgerKeyNotFoundError = "Key not found" ) -var _ KVStore = &badgerKVStore{} -var _ smt.MapStore = &badgerKVStore{} +var ( + _ KVStore = &badgerKVStore{} + _ smt.MapStore = &badgerKVStore{} +) var ( ErrKVStoreExists = errors.New("kvstore already exists") diff --git a/persistence/module.go b/persistence/module.go index 74f148413..42e6f2c1d 100644 --- a/persistence/module.go +++ b/persistence/module.go @@ -3,9 +3,9 @@ package persistence import ( "context" "fmt" - "log" "github.com/jackc/pgx/v5" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/persistence/indexer" "github.com/pokt-network/pocket/persistence/kvstore" "github.com/pokt-network/pocket/runtime/configs" @@ -31,6 +31,8 @@ type persistenceModule struct { txIndexer indexer.TxIndexer stateTrees *stateTrees + logger modules.Logger + // TECHDEBT: Need to implement context pooling (for writes), timeouts (for read & writes), etc... writeContext *PostgresContext // only one write context is allowed at a time } @@ -93,14 +95,15 @@ func (*persistenceModule) Create(bus modules.Bus) (modules.Module, error) { } else { // This configurations will connect to the SQL database and key-value stores specified // in the configurations and connected to those. - log.Println("Loading state from disk...") + logger.Global.Info().Msg("Loading state from disk...") } return m, nil } func (m *persistenceModule) Start() error { - log.Println("Starting persistence module...") + m.logger.Info().Msg("Starting module...") + m.logger = logger.Global.CreateLoggerForModule(m.GetModuleName()) return nil } @@ -119,7 +122,7 @@ func (m *persistenceModule) SetBus(bus modules.Bus) { func (m *persistenceModule) GetBus() modules.Bus { if m.bus == nil { - log.Fatalf("PocketBus is not initialized") + logger.Global.Fatal().Msg("PocketBus is not initialized") } return m.bus } @@ -148,13 +151,14 @@ func (m *persistenceModule) NewRWContext(height int64) (modules.PersistenceRWCon stateHash: "", + logger: m.logger, + blockStore: m.blockStore, txIndexer: m.txIndexer, stateTrees: m.stateTrees, } return m.writeContext, nil - } func (m *persistenceModule) NewReadContext(height int64) (modules.PersistenceReadContext, error) { @@ -178,6 +182,8 @@ func (m *persistenceModule) NewReadContext(height int64) (modules.PersistenceRea stateHash: "", + logger: m.logger, + blockStore: m.blockStore, txIndexer: m.txIndexer, stateTrees: m.stateTrees, @@ -187,7 +193,7 @@ func (m *persistenceModule) NewReadContext(height int64) (modules.PersistenceRea func (m *persistenceModule) ReleaseWriteContext() error { if m.writeContext != nil { if err := m.writeContext.resetContext(); err != nil { - log.Println("[TODO][ERROR] Error releasing write context...", err) + logger.Global.Error().Err(err).Msg("Error releasing write context") } m.writeContext = nil } diff --git a/persistence/state.go b/persistence/state.go index cb4ec2a85..917b8023a 100644 --- a/persistence/state.go +++ b/persistence/state.go @@ -5,7 +5,6 @@ import ( "crypto/sha256" "encoding/hex" "fmt" - "log" "github.com/celestiaorg/smt" "github.com/pokt-network/pocket/persistence/kvstore" @@ -181,7 +180,7 @@ func (p *PostgresContext) updateMerkleTrees() (string, error) { // Default default: - log.Fatalf("Not handled yet in state commitment update. Merkle tree #{%v}\n", treeType) + p.logger.Fatal().Msgf("Not handled yet in state commitment update. Merkle tree #{%v}", treeType) } } diff --git a/persistence/types/gov_test.go b/persistence/types/gov_test.go index f3dea6c76..870789f7c 100644 --- a/persistence/types/gov_test.go +++ b/persistence/types/gov_test.go @@ -142,5 +142,4 @@ func TestInsertParams(t *testing.T) { } }) } - } diff --git a/rpc/doc/CHANGELOG.md b/rpc/doc/CHANGELOG.md index 9baf6cdd1..3bba779f0 100644 --- a/rpc/doc/CHANGELOG.md +++ b/rpc/doc/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.0.0.7] - 2023-02-04 + +- Changed log lines to utilize new logger module. + ## [0.0.0.6] - 2023-01-23 - Added `pprof` http server feature flag via build tags diff --git a/rpc/handlers.go b/rpc/handlers.go index 10fb8fbb3..10fc44834 100644 --- a/rpc/handlers.go +++ b/rpc/handlers.go @@ -2,7 +2,6 @@ package rpc import ( "encoding/hex" - "log" "net/http" "github.com/labstack/echo/v4" @@ -58,12 +57,12 @@ func (s *rpcServer) broadcastMessage(msgBz []byte) error { anyUtilityMessage, err := codec.GetCodec().ToAny(utilMsg) if err != nil { - log.Printf("[ERROR] Failed to create Any proto from transaction gossip: %v", err) + s.logger.Error().Err(err).Msg("Failed to create Any proto from transaction gossip") return err } if err := s.GetBus().GetP2PModule().Broadcast(anyUtilityMessage); err != nil { - log.Printf("[ERROR] Failed to broadcast utility message: %v", err) + s.logger.Error().Err(err).Msg("Failed to broadcast utility message") return err } return nil diff --git a/rpc/module.go b/rpc/module.go index d221c50bd..332b116e2 100644 --- a/rpc/module.go +++ b/rpc/module.go @@ -1,22 +1,21 @@ package rpc import ( - "log" // importing because used by code-generated files that are git ignored and to allow go mod tidy and go mod vendor to function properly _ "github.com/getkin/kin-openapi/openapi3" _ "github.com/labstack/echo/v4" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/runtime/configs" "github.com/pokt-network/pocket/shared/modules" ) -var ( - _ modules.RPCModule = &rpcModule{} -) +var _ modules.RPCModule = &rpcModule{} type rpcModule struct { bus modules.Bus + logger modules.Logger config *configs.RPCConfig } @@ -40,7 +39,8 @@ func (*rpcModule) Create(bus modules.Bus) (modules.Module, error) { } func (u *rpcModule) Start() error { - go NewRPCServer(u.GetBus()).StartRPC(u.config.Port, u.config.Timeout) + u.logger = logger.Global.CreateLoggerForModule(u.GetModuleName()) + go NewRPCServer(u.GetBus()).StartRPC(u.config.Port, u.config.Timeout, u.logger) return nil } @@ -58,7 +58,7 @@ func (u *rpcModule) SetBus(bus modules.Bus) { func (u *rpcModule) GetBus() modules.Bus { if u.bus == nil { - log.Fatalf("Bus is not initialized") + u.logger.Fatal().Msg("Bus is not initialized") } return u.bus } diff --git a/rpc/noop_module.go b/rpc/noop_module.go index abbb8b4a6..daad5b40c 100644 --- a/rpc/noop_module.go +++ b/rpc/noop_module.go @@ -6,9 +6,7 @@ import ( "github.com/pokt-network/pocket/shared/modules" ) -var ( - _ modules.RPCModule = &noopRpcModule{} -) +var _ modules.RPCModule = &noopRpcModule{} type noopRpcModule struct{} diff --git a/rpc/server.go b/rpc/server.go index f862bcd8c..d07142286 100644 --- a/rpc/server.go +++ b/rpc/server.go @@ -1,7 +1,6 @@ package rpc import ( - "log" "net/http" "time" @@ -12,23 +11,41 @@ import ( type rpcServer struct { bus modules.Bus + + logger modules.Logger } -var _ ServerInterface = &rpcServer{} -var _ modules.IntegratableModule = &rpcServer{} +var ( + _ ServerInterface = &rpcServer{} + _ modules.IntegratableModule = &rpcServer{} +) func NewRPCServer(bus modules.Bus) *rpcServer { s := &rpcServer{} s.SetBus(bus) + return s } -func (s *rpcServer) StartRPC(port string, timeout uint64) { - log.Printf("Starting RPC on port %s...\n", port) +func (s *rpcServer) StartRPC(port string, timeout uint64, logger modules.Logger) { + s.logger = logger + + s.logger.Info().Msgf("Starting RPC on port " + port) e := echo.New() middlewares := []echo.MiddlewareFunc{ - middleware.Logger(), + middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{ + LogURI: true, + LogStatus: true, + LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error { + s.logger.Info(). + Str("URI", v.URI). + Int("status", v.Status). + Msg("request") + + return nil + }, + }), middleware.TimeoutWithConfig(middleware.TimeoutConfig{ Skipper: middleware.DefaultSkipper, ErrorMessage: "Request timed out", @@ -36,7 +53,7 @@ func (s *rpcServer) StartRPC(port string, timeout uint64) { }), } if s.GetBus().GetRuntimeMgr().GetConfig().RPC.UseCors { - log.Println("Enabling CORS middleware") + s.logger.Info().Msg("Enabling CORS middleware") middlewares = append(middlewares, middleware.CORS()) } e.Use( @@ -46,7 +63,7 @@ func (s *rpcServer) StartRPC(port string, timeout uint64) { RegisterHandlers(e, s) if err := e.Start(":" + port); err != http.ErrServerClosed { - log.Fatal(err) + s.logger.Fatal().Err(err).Msg("RPC server failed to start") } } diff --git a/runtime/docs/CHANGELOG.md b/runtime/docs/CHANGELOG.md index 2551144d8..70d593219 100644 --- a/runtime/docs/CHANGELOG.md +++ b/runtime/docs/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.0.0.12] - 2023-02-04 + +- Changed log lines to utilize new logger module. + ## [0.0.0.11] - 2023-02-03 - Updated to display the warning message about the telemetry module not registered only once diff --git a/runtime/manager.go b/runtime/manager.go index 4b3faa051..6e9ecb62a 100644 --- a/runtime/manager.go +++ b/runtime/manager.go @@ -10,6 +10,7 @@ import ( "github.com/benbjohnson/clock" "github.com/mitchellh/mapstructure" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/runtime/configs" "github.com/pokt-network/pocket/runtime/genesis" cryptoPocket "github.com/pokt-network/pocket/shared/crypto" @@ -28,7 +29,7 @@ type Manager struct { } func NewManager(config *configs.Config, genesis *genesis.GenesisState, options ...func(*Manager)) *Manager { - var mgr = new(Manager) + mgr := new(Manager) bus, err := CreateBus(mgr) if err != nil { log.Fatalf("[ERROR] Failed to initialize bus: %v", err) @@ -58,10 +59,10 @@ func NewManagerFromFiles(configPath, genesisPath string, options ...func(*Manage // // Useful for testing and when the user doesn't want to rely on the filesystem and instead intends plugging in different configuration management system. func NewManagerFromReaders(configReader, genesisReader io.Reader, options ...func(*Manager)) *Manager { - var cfg = configs.NewDefaultConfig() + cfg := configs.NewDefaultConfig() parseFromReader(configReader, cfg) - var genesisState = new(genesis.GenesisState) + genesisState := new(genesis.GenesisState) parseFromReader(genesisReader, genesisState) return NewManager(cfg, genesisState, options...) @@ -120,11 +121,10 @@ func parseFiles(configJSONPath, genesisJSONPath string) (config *configs.Config, func parseFromReader[T *configs.Config | *genesis.GenesisState](reader io.Reader, target T) { bz, err := io.ReadAll(reader) if err != nil { - log.Fatalf("[ERROR] Failed to read from reader: %v", err) - + logger.Global.Err(err).Msg("Failed to read from reader") } if err := json.Unmarshal(bz, target); err != nil { - log.Fatalf("[ERROR] Failed to unmarshal: %v", err) + logger.Global.Err(err).Msg("Failed to unmarshal") } } @@ -133,7 +133,7 @@ func parseFromReader[T *configs.Config | *genesis.GenesisState](reader io.Reader func WithRandomPK() func(*Manager) { privateKey, err := cryptoPocket.GeneratePrivateKey() if err != nil { - log.Fatalf("unable to generate private key") + logger.Global.Fatal().Err(err).Msg("unable to generate private key") } return WithPK(privateKey.String()) diff --git a/runtime/test_artifacts/gov.go b/runtime/test_artifacts/gov.go index 61f8a584e..77b088daa 100644 --- a/runtime/test_artifacts/gov.go +++ b/runtime/test_artifacts/gov.go @@ -11,9 +11,7 @@ import ( // TODO (Team) this entire file should be re-scoped. DefaultParameters are only a testing thing because prod defers to the genesis file -var ( - DefaultParamsOwner, _ = crypto.NewPrivateKey("ff538589deb7f28bbce1ba68b37d2efc0eaa03204b36513cf88422a875559e38d6cbe0430ddd85a5e48e0c99ef3dea47bf0d1a83c6e6ad1640f72201dc8a0120") -) +var DefaultParamsOwner, _ = crypto.NewPrivateKey("ff538589deb7f28bbce1ba68b37d2efc0eaa03204b36513cf88422a875559e38d6cbe0430ddd85a5e48e0c99ef3dea47bf0d1a83c6e6ad1640f72201dc8a0120") func DefaultParams() *genesis.Params { return &genesis.Params{ diff --git a/shared/CHANGELOG.md b/shared/CHANGELOG.md index 251d30f57..cbe754feb 100644 --- a/shared/CHANGELOG.md +++ b/shared/CHANGELOG.md @@ -7,6 +7,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.0.0.21] - 2023-02-04 + +- Changed log lines to utilize new logger module. +- Added example to Readme how to initiate a logger using new logger module. + ## [0.0.0.20] - 2023-02-03 - Introduced `GenericFIFOList` to handle generic FIFO mempool lists (can contain duplicates) diff --git a/shared/modules/doc/README.md b/shared/modules/doc/README.md index adc964b82..d7fdddea1 100644 --- a/shared/modules/doc/README.md +++ b/shared/modules/doc/README.md @@ -35,10 +35,10 @@ genesis ├── test_artifacts # the central point of all testing code (WIP) │   ├── generator.go # generate the genesis and config.json for tests and build │   ├── gov.go # default testing parameters - ``` TODO(#235): Update once runtime configs are implemented + ### Module Typical Usage Example #### Create the module @@ -78,6 +78,17 @@ if err != nil { } ``` +##### Add a logger to the module + +When defining the start function for the module, it is essential to initialise a namespace logger as well: + +```golang +func (m *newModule) Start() error { + m.logger = logger.Global.CreateLoggerForModule(u.GetModuleName()) + ... +} +``` + #### Get the module `bus` The bus may be accessed by the module object at anytime using the `getter` diff --git a/shared/modules/module.go b/shared/modules/module.go index 2fec4a3a0..7e9ef989e 100644 --- a/shared/modules/module.go +++ b/shared/modules/module.go @@ -34,6 +34,5 @@ type P2PAddressableModule interface { } type ObservableModule interface { - InitLogger() GetLogger() Logger } diff --git a/shared/node.go b/shared/node.go index a5304c7f6..da12a9e4d 100644 --- a/shared/node.go +++ b/shared/node.go @@ -1,8 +1,6 @@ package shared import ( - "log" - "github.com/pokt-network/pocket/consensus" "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/p2p" @@ -59,7 +57,7 @@ func (m *Node) Create(bus modules.Bus) (modules.Module, error) { } func (node *Node) Start() error { - log.Println("About to start pocket node modules...") + logger.Global.Info().Msg("About to start pocket node modules...") // IMPORTANT: Order of module startup here matters @@ -94,19 +92,19 @@ func (node *Node) Start() error { } node.GetBus().PublishEventToBus(signalNodeStartedEvent) - log.Println("About to start pocket node main loop...") + logger.Global.Info().Msg("About to start pocket node main loop...") // While loop lasting throughout the entire lifecycle of the node to handle asynchronous events for { event := node.GetBus().GetBusEvent() if err := node.handleEvent(event); err != nil { - log.Println("Error handling event:", err) + logger.Global.Error().Err(err).Msg("Error handling event") } } } func (node *Node) Stop() error { - log.Println("Stopping pocket node...") + logger.Global.Info().Msg("Stopping pocket node...") return nil } @@ -116,7 +114,7 @@ func (m *Node) SetBus(bus modules.Bus) { func (m *Node) GetBus() modules.Bus { if m.bus == nil { - log.Fatalf("PocketBus is not initialized") + logger.Global.Fatal().Msg("PocketBus is not initialized") } return m.bus } @@ -125,7 +123,7 @@ func (node *Node) handleEvent(message *messaging.PocketEnvelope) error { contentType := message.GetContentType() switch contentType { case messaging.NodeStartedEventType: - log.Println("[NOOP] Received NodeStartedEvent") + logger.Global.Info().Msg("Received NodeStartedEvent") case consensus.HotstuffMessageContentType: return node.GetBus().GetConsensusModule().HandleMessage(message.Content) case utility.TransactionGossipMessageContentType: @@ -133,7 +131,7 @@ func (node *Node) handleEvent(message *messaging.PocketEnvelope) error { case messaging.DebugMessageEventType: return node.handleDebugMessage(message) default: - log.Printf("[WARN] Unsupported message content type: %s \n", contentType) + logger.Global.Warn().Msgf("Unsupported message content type: %s", contentType) } return nil } @@ -158,7 +156,7 @@ func (node *Node) handleDebugMessage(message *messaging.PocketEnvelope) error { return node.GetBus().GetPersistenceModule().HandleDebugMessage(debugMessage) // Default Debug default: - log.Printf("Debug message: %s \n", debugMessage.Message) + logger.Global.Debug().Msgf("Received DebugMessage: %s", debugMessage.Message) } return nil diff --git a/telemetry/CHANGELOG.md b/telemetry/CHANGELOG.md index b7fc7b7da..54429bcf4 100644 --- a/telemetry/CHANGELOG.md +++ b/telemetry/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.0.0.4] - 2023-02-04 + +- Changed log lines to utilize new logger module. + ## [0.0.0.3] - 2023-01-19 - Rewrite `interface{}` to `any` diff --git a/telemetry/noop_module.go b/telemetry/noop_module.go index b7b2f9ddb..416cc1a1d 100644 --- a/telemetry/noop_module.go +++ b/telemetry/noop_module.go @@ -2,8 +2,8 @@ package telemetry import ( "fmt" - "log" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/shared/modules" "github.com/prometheus/client_golang/prometheus" ) @@ -19,7 +19,7 @@ type NoopTelemetryModule struct { } func NOOP(args ...any) { - log.Printf("\n[telemetry=noop][%s]\n", args) + logger.Global.Debug().Msg("NOOP") } func CreateNoopTelemetryModule(bus modules.Bus) (modules.Module, error) { @@ -53,7 +53,7 @@ func (m *NoopTelemetryModule) SetBus(bus modules.Bus) { func (m *NoopTelemetryModule) GetBus() modules.Bus { if m.bus == nil { - log.Fatalf("PocketBus is not initialized") + logger.Global.Fatal().Msg("PocketBus is not initialized") } return m.bus } diff --git a/telemetry/prometheus_module.go b/telemetry/prometheus_module.go index 286fffa64..6f90a7dad 100644 --- a/telemetry/prometheus_module.go +++ b/telemetry/prometheus_module.go @@ -2,9 +2,9 @@ package telemetry import ( "fmt" - "log" "net/http" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/runtime/configs" "github.com/pokt-network/pocket/shared/modules" "github.com/prometheus/client_golang/prometheus" @@ -25,6 +25,8 @@ type PrometheusTelemetryModule struct { bus modules.Bus config *configs.TelemetryConfig + logger modules.Logger + counters map[string]prometheus.Counter gauges map[string]prometheus.Gauge gaugeVectors map[string]prometheus.GaugeVec @@ -52,12 +54,16 @@ func (*PrometheusTelemetryModule) Create(bus modules.Bus) (modules.Module, error } func (m *PrometheusTelemetryModule) Start() error { - log.Printf("\nPrometheus metrics exporter: Starting at %s%s...\n", m.config.Address, m.config.Endpoint) + uri := m.config.GetAddress() + m.config.GetEndpoint() + + m.logger = logger.Global.CreateLoggerForModule(m.GetModuleName()) + + m.logger.Info().Str("address", uri).Msg("Starting Prometheus metrics exporter...") http.Handle(m.config.Endpoint, promhttp.Handler()) go http.ListenAndServe(m.config.Address, nil) - log.Println("Prometheus metrics exporter started: OK") + m.logger.Info().Str("address", uri).Msg("Prometheus metrics exporter started") return nil } @@ -76,7 +82,7 @@ func (m *PrometheusTelemetryModule) GetModuleName() string { func (m *PrometheusTelemetryModule) GetBus() modules.Bus { if m.bus == nil { - log.Fatalf("PocketBus is not initialized") + m.logger.Fatal().Msg("PocketBus is not initialized") } return m.bus } @@ -92,8 +98,14 @@ func (m *PrometheusTelemetryModule) GetEventMetricsAgent() modules.EventMetricsA // will be removed in the future in favor of more thorough event metrics tooling. // TECHDEBT(team): Deprecate using logs for event metrics for a more sophisticated and durable solution func (m *PrometheusTelemetryModule) EmitEvent(namespace, event string, labels ...any) { - logArgs := append([]any{"[EVENT]", namespace, event}, labels...) - log.Println(logArgs...) + logArgs := map[string]any{ + "level": "EVENT", + "namespace": namespace, + "event": event, + "labels": labels, + } + + m.logger.Info().Fields(logArgs).Msg("Event emitted") } func (m *PrometheusTelemetryModule) GetTimeSeriesAgent() modules.TimeSeriesAgent { @@ -102,7 +114,7 @@ func (m *PrometheusTelemetryModule) GetTimeSeriesAgent() modules.TimeSeriesAgent func (p *PrometheusTelemetryModule) CounterRegister(name string, description string) { if _, exists := p.counters[name]; exists { - log.Printf("[WARNING] Trying to register and already registered counter: %s\n", name) + p.logger.Warn().Str("counter", name).Msg("Trying to register and already registered counter") return } @@ -114,7 +126,7 @@ func (p *PrometheusTelemetryModule) CounterRegister(name string, description str func (p *PrometheusTelemetryModule) CounterIncrement(name string) { if _, exists := p.counters[name]; !exists { - log.Printf("[WARNING] Trying to increment a non-existent counter: %s\n", name) + p.logger.Warn().Str("counter", name).Msg("Trying to increment a non-existent counter") return } @@ -123,7 +135,7 @@ func (p *PrometheusTelemetryModule) CounterIncrement(name string) { func (p *PrometheusTelemetryModule) GaugeRegister(name string, description string) { if _, exists := p.gauges[name]; exists { - log.Printf("[WARNING] Trying to register and already registered gauge: %s\n", name) + p.logger.Warn().Str("gauge", name).Msg("Trying to register and already registered gauge") return } @@ -191,7 +203,7 @@ func (p *PrometheusTelemetryModule) GaugeSub(name string, value float64) (promet func (p *PrometheusTelemetryModule) GaugeVecRegister(namespace, module, name, description string, labels []string) { if _, exists := p.counters[name]; exists { - log.Printf("[WARNING] Trying to register and already registered vector gauge: %s\n", name) + p.logger.Warn().Str("gauge_vector", name).Msg("Trying to register and already registered gauge vector") return } diff --git a/utility/block.go b/utility/block.go index 4e8e18fc2..2c7129682 100644 --- a/utility/block.go +++ b/utility/block.go @@ -1,7 +1,6 @@ package utility import ( - "log" "math/big" coreTypes "github.com/pokt-network/pocket/shared/core/types" @@ -65,7 +64,7 @@ func (u *UtilityContext) CreateAndApplyProposalBlock(proposer []byte, maxTransac continue } if err := u.Context.IndexTransaction(txResult); err != nil { - log.Fatalf("TODO(#327): We can apply the transaction but not index it. Crash the process for now: %v\n", err) + u.logger.Fatal().Err(err).Msg("TODO(#327): We can apply the transaction but not index it. Crash the process for now") } transactions = append(transactions, txBytes) @@ -78,9 +77,9 @@ func (u *UtilityContext) CreateAndApplyProposalBlock(proposer []byte, maxTransac // return the app hash (consensus module will get the validator set directly) stateHash, err := u.Context.ComputeStateHash() if err != nil { - log.Fatalf("Updating the app hash failed: %v. TODO: Look into roll-backing the entire commit...\n", err) + u.logger.Fatal().Err(err).Msg("Updating the app hash failed. TODO: Look into roll-backing the entire commit...") } - log.Println("CreateAndApplyProposalBlock - computed state hash:", stateHash) + u.logger.Info().Msgf("CreateAndApplyProposalBlock - computed state hash: %s", stateHash) return stateHash, transactions, err } @@ -118,7 +117,7 @@ func (u *UtilityContext) ApplyBlock() (string, error) { } if err := u.Context.IndexTransaction(txResult); err != nil { - log.Fatalf("TODO(#327): We can apply the transaction but not index it. Crash the process for now: %v\n", err) + u.logger.Fatal().Err(err).Msg("TODO(#327): We can apply the transaction but not index it. Crash the process for now") } // TODO: if found, remove transaction from mempool. @@ -135,10 +134,10 @@ func (u *UtilityContext) ApplyBlock() (string, error) { // return the app hash (consensus module will get the validator set directly) stateHash, err := u.Context.ComputeStateHash() if err != nil { - log.Fatalf("Updating the app hash failed: %v. TODO: Look into roll-backing the entire commit...\n", err) + u.logger.Fatal().Err(err).Msg("Updating the app hash failed. TODO: Look into roll-backing the entire commit...") return "", typesUtil.ErrAppHash(err) } - log.Println("ApplyBlock - computed state hash:", stateHash) + u.logger.Info().Msgf("ApplyBlock - computed state hash: %s", stateHash) // return the app hash; consensus module will get the validator set directly return stateHash, nil diff --git a/utility/context.go b/utility/context.go index 238415bc4..4b1a83525 100644 --- a/utility/context.go +++ b/utility/context.go @@ -17,6 +17,9 @@ type UtilityContext struct { // Data related to the Block being proposed // TECHDEBT: When we consolidate everything to have a single `Block` object (a struct backed by a protobuf), // this can be simplified to just point to that object. + + logger modules.Logger + proposalProposerAddr []byte proposalStateHash string proposalBlockTxs [][]byte @@ -39,6 +42,7 @@ func (u *utilityModule) NewContext(height int64) (modules.UtilityContext, error) return &UtilityContext{ bus: u.GetBus(), Height: height, + logger: u.logger, Context: &Context{ PersistenceRWContext: ctx, SavePoints: make([][]byte, 0), diff --git a/utility/doc/CHANGELOG.md b/utility/doc/CHANGELOG.md index 985f4f18d..9dabbe4cb 100644 --- a/utility/doc/CHANGELOG.md +++ b/utility/doc/CHANGELOG.md @@ -7,6 +7,10 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.0.0.23] - 2023-02-04 + +- Changed log lines to utilize new logger module. + ## [0.0.0.22] - 2023-02-03 - Introduced `txFIFOMempool` which extends the new `GenericFIFOSet` in order to replace the legacy logic diff --git a/utility/gov.go b/utility/gov.go index 12e7df710..1a683ab05 100644 --- a/utility/gov.go +++ b/utility/gov.go @@ -1,7 +1,6 @@ package utility import ( - "log" "math/big" coreTypes "github.com/pokt-network/pocket/shared/core/types" @@ -30,7 +29,7 @@ func (u *UtilityContext) UpdateParam(paramName string, value any) typesUtil.Erro default: break } - log.Fatalf("unhandled value type %T for %v", value, value) + u.logger.Fatal().Msgf("unhandled value type %T for %v", value, value) return typesUtil.ErrUnknownParam(paramName) } @@ -543,7 +542,6 @@ func (u *UtilityContext) GetFee(msg typesUtil.Message, actorType coreTypes.Actor default: return nil, typesUtil.ErrUnknownMessage(x) } - return nil, nil } func (u *UtilityContext) GetMessageChangeParameterSignerCandidates(msg *typesUtil.MessageChangeParameter) ([][]byte, typesUtil.Error) { @@ -561,7 +559,7 @@ func (u *UtilityContext) getBigIntParam(paramName string) (*big.Int, typesUtil.E } value, err := store.GetStringParam(paramName, height) if err != nil { - log.Printf("err: %v\n", err) + u.logger.Err(err) return nil, typesUtil.ErrGetParam(paramName, err) } return typesUtil.StringToBigInt(value) diff --git a/utility/module.go b/utility/module.go index 30e66e352..1f25d9f0e 100644 --- a/utility/module.go +++ b/utility/module.go @@ -2,8 +2,8 @@ package utility import ( "fmt" - "log" + "github.com/pokt-network/pocket/logger" "github.com/pokt-network/pocket/runtime/configs" "github.com/pokt-network/pocket/shared/codec" "github.com/pokt-network/pocket/shared/mempool" @@ -12,13 +12,16 @@ import ( "google.golang.org/protobuf/types/known/anypb" ) -var _ modules.UtilityModule = &utilityModule{} -var _ modules.Module = &utilityModule{} +var ( + _ modules.UtilityModule = &utilityModule{} + _ modules.Module = &utilityModule{} +) type utilityModule struct { bus modules.Bus config *configs.UtilityConfig + logger modules.Logger mempool mempool.TXMempool } @@ -46,6 +49,7 @@ func (*utilityModule) Create(bus modules.Bus) (modules.Module, error) { } func (u *utilityModule) Start() error { + u.logger = logger.Global.CreateLoggerForModule(u.GetModuleName()) return nil } @@ -63,7 +67,7 @@ func (u *utilityModule) SetBus(bus modules.Bus) { func (u *utilityModule) GetBus() modules.Bus { if u.bus == nil { - log.Fatalf("Bus is not initialized") + u.logger.Fatal().Msg("Bus is not initialized") } return u.bus } @@ -82,7 +86,7 @@ func (u *utilityModule) HandleMessage(message *anypb.Any) error { if err := u.CheckTransaction(transactionGossipMsg.Tx); err != nil { return err } - log.Println("MEMPOOOL: Successfully added a new message to the mempool!") + u.logger.Info().Str("source", "MEMPOOL").Msg("Successfully added a new message to the mempool!") default: return types.ErrUnknownMessageType(message.MessageName()) } diff --git a/utility/types/message.go b/utility/types/message.go index 7ddda49ec..0a7c3779f 100644 --- a/utility/types/message.go +++ b/utility/types/message.go @@ -50,13 +50,15 @@ type Message interface { GetMessageRecipient() string } -var _ Message = &MessageSend{} -var _ Message = &MessageStake{} -var _ Message = &MessageEditStake{} -var _ Message = &MessageUnstake{} -var _ Message = &MessageUnpause{} -var _ Message = &MessageChangeParameter{} -var _ Message = &MessageDoubleSign{} +var ( + _ Message = &MessageSend{} + _ Message = &MessageStake{} + _ Message = &MessageEditStake{} + _ Message = &MessageUnstake{} + _ Message = &MessageUnpause{} + _ Message = &MessageChangeParameter{} + _ Message = &MessageDoubleSign{} +) func (msg *MessageSend) GetActorType() coreTypes.ActorType { return coreTypes.ActorType_ACTOR_TYPE_UNSPECIFIED // there's no actor type for message send, so return zero to allow fee retrieval