From 56100a7a6c0b91ccf414066096b12a071a88c615 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Milo=C5=A1=20=C5=BDivkovi=C4=87?= Date: Tue, 16 Apr 2024 18:23:54 +0200 Subject: [PATCH] feat: slightly improve node log lines (#1916) ## Description This PR improves the log lines produced by the node binary. Before: ![cast2](https://github.com/gnolang/gno/assets/16712663/84d0b570-e7a3-410a-bb93-f20581d95e71) After: ![cast1](https://github.com/gnolang/gno/assets/16712663/bdca272d-9c2a-4249-8f70-a0c383bd7e6c)
Contributors' checklist... - [x] Added new tests, or not needed, or not feasible - [x] Provided an example (e.g. screenshot) to aid review or the PR is self-explanatory - [x] Updated the official documentation or not needed - [x] No breaking changes were made, or a `BREAKING CHANGE: xxx` message was included in the description - [ ] Added references to related issues and PRs - [ ] Provided any useful hints for running manual tests - [ ] Added new benchmarks to [generated graphs](https://gnoland.github.io/benchmarks), if any. More info [here](https://github.com/gnolang/gno/blob/master/.benchmarks/README.md).
--- gno.land/cmd/gnoland/start.go | 15 ++++++- gno.land/cmd/gnoland/start_test.go | 69 +++++++++++++----------------- gno.land/pkg/gnoland/app.go | 13 +++--- gno.land/pkg/sdk/vm/keeper.go | 8 +--- tm2/pkg/bft/consensus/state.go | 62 +++++++++++++++++++++++---- tm2/pkg/p2p/switch.go | 7 ++- 6 files changed, 111 insertions(+), 63 deletions(-) diff --git a/gno.land/cmd/gnoland/start.go b/gno.land/cmd/gnoland/start.go index 921fcc89640..a991e2e0dc0 100644 --- a/gno.land/cmd/gnoland/start.go +++ b/gno.land/cmd/gnoland/start.go @@ -29,6 +29,15 @@ import ( "go.uber.org/zap/zapcore" ) +var startGraphic = fmt.Sprintf(` + __ __ + ____ _____ ____ / /___ _____ ____/ / + / __ %c/ __ \/ __ \/ / __ %c/ __ \/ __ / + / /_/ / / / / /_/ / / /_/ / / / / /_/ / + \__, /_/ /_/\____/_/\__,_/_/ /_/\__,_/ +/____/ +`, '`', '`') + type startCfg struct { gnoRootDir string skipFailingGenesisTxs bool @@ -268,13 +277,15 @@ func execStart(c *startCfg, io commands.IO) error { } cfg.LocalApp = gnoApp + if logFormat != log.JSONFormat { + io.Println(startGraphic) + } + gnoNode, err := node.DefaultNewNode(cfg, logger) if err != nil { return fmt.Errorf("error in creating node: %w", err) } - fmt.Fprintln(io.Err(), "Node created.") - if c.skipStart { io.ErrPrintln("'--skip-start' is set. Exiting.") return nil diff --git a/gno.land/cmd/gnoland/start_test.go b/gno.land/cmd/gnoland/start_test.go index 661d329e103..2f266d8a879 100644 --- a/gno.land/cmd/gnoland/start_test.go +++ b/gno.land/cmd/gnoland/start_test.go @@ -3,52 +3,43 @@ package main import ( "bytes" "context" - "os" - "path/filepath" - "strings" "testing" + "time" "github.com/gnolang/gno/tm2/pkg/commands" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) func TestStartInitialize(t *testing.T) { t.Parallel() - cases := []struct { - args []string - }{ - {[]string{"start", "--skip-start", "--skip-failing-genesis-txs"}}, - // {[]string{"--skip-start"}}, - // FIXME: test seems flappy as soon as we have multiple cases. - } - os.Chdir(filepath.Join("..", "..")) // go to repo's root dir - - for _, tc := range cases { - tc := tc - name := strings.Join(tc.args, " ") - t.Run(name, func(t *testing.T) { - t.Parallel() - - mockOut := new(bytes.Buffer) - mockErr := new(bytes.Buffer) - io := commands.NewTestIO() - io.SetOut(commands.WriteNopCloser(mockOut)) - io.SetErr(commands.WriteNopCloser(mockErr)) - cmd := newRootCmd(io) - - t.Logf(`Running "gnoland %s"`, strings.Join(tc.args, " ")) - err := cmd.ParseAndRun(context.Background(), tc.args) - require.NoError(t, err) - - stdout := mockOut.String() - stderr := mockErr.String() - - require.Contains(t, stderr, "Node created.", "failed to create node") - require.Contains(t, stderr, "'--skip-start' is set. Exiting.", "not exited with skip-start") - require.NotContains(t, stdout, "panic:") - }) - } + var ( + nodeDir = t.TempDir() + + args = []string{ + "start", + "--skip-start", + "--skip-failing-genesis-txs", + "--data-dir", + nodeDir, + } + ) + + // Prepare the IO + mockOut := new(bytes.Buffer) + mockErr := new(bytes.Buffer) + io := commands.NewTestIO() + io.SetOut(commands.WriteNopCloser(mockOut)) + io.SetErr(commands.WriteNopCloser(mockErr)) + + // Create and run the command + ctx, cancelFn := context.WithTimeout(context.Background(), 5*time.Second) + defer cancelFn() + + cmd := newRootCmd(io) + require.NoError(t, cmd.ParseAndRun(ctx, args)) + + // Make sure the directory is created + assert.DirExists(t, nodeDir) } - -// TODO: test various configuration files? diff --git a/gno.land/pkg/gnoland/app.go b/gno.land/pkg/gnoland/app.go index f67b86fd735..d1978e76563 100644 --- a/gno.land/pkg/gnoland/app.go +++ b/gno.land/pkg/gnoland/app.go @@ -7,7 +7,6 @@ import ( "github.com/gnolang/gno/gno.land/pkg/sdk/vm" "github.com/gnolang/gno/gnovm/pkg/gnoenv" - "github.com/gnolang/gno/tm2/pkg/amino" abci "github.com/gnolang/gno/tm2/pkg/bft/abci/types" dbm "github.com/gnolang/gno/tm2/pkg/db" "github.com/gnolang/gno/tm2/pkg/log" @@ -169,13 +168,15 @@ func InitChainer(baseApp *sdk.BaseApp, acctKpr auth.AccountKeeperI, bankKpr bank } // Run genesis txs. - for i, tx := range genState.Txs { + for _, tx := range genState.Txs { res := baseApp.Deliver(tx) if res.IsErr() { - ctx.Logger().Error("LOG", "log", res.Log) - ctx.Logger().Error(fmt.Sprintf("#%d", i), "value", string(amino.MustMarshalJSON(tx))) - } else { - ctx.Logger().Info("SUCCESS:", "value", string(amino.MustMarshalJSON(tx))) + ctx.Logger().Error( + "Unable to deliver genesis tx", + "log", res.Log, + "error", res.Error, + "gas-used", res.GasUsed, + ) } resHandler(ctx, tx, res) diff --git a/gno.land/pkg/sdk/vm/keeper.go b/gno.land/pkg/sdk/vm/keeper.go index 67710be620c..e9223143bf5 100644 --- a/gno.land/pkg/sdk/vm/keeper.go +++ b/gno.land/pkg/sdk/vm/keeper.go @@ -200,7 +200,6 @@ func (vm *VMKeeper) AddPackage(ctx sdk.Context, msg MsgAddPackage) error { defer m2.Release() m2.RunMemPackage(memPkg, true) - ctx.Logger().Info("CPUCYCLES", "addpkg", m2.Cycles) return nil } @@ -285,7 +284,7 @@ func (vm *VMKeeper) Call(ctx sdk.Context, msg MsgCall) (res string, err error) { m.Release() }() rtvs := m.Eval(xn) - ctx.Logger().Info("CPUCYCLES call", "num-cycles", m.Cycles) + for i, rtv := range rtvs { res = res + rtv.String() if i < len(rtvs)-1 { @@ -349,7 +348,6 @@ func (vm *VMKeeper) Run(ctx sdk.Context, msg MsgRun) (res string, err error) { }) defer m.Release() _, pv := m.RunMemPackage(memPkg, false) - ctx.Logger().Info("CPUCYCLES", "addpkg", m.Cycles) m2 := gno.NewMachineWithOptions( gno.MachineOptions{ @@ -370,9 +368,7 @@ func (vm *VMKeeper) Run(ctx sdk.Context, msg MsgRun) (res string, err error) { m2.Release() }() m2.RunMain() - ctx.Logger().Info("CPUCYCLES call", - "cycles", m2.Cycles, - ) + res = buf.String() return res, nil } diff --git a/tm2/pkg/bft/consensus/state.go b/tm2/pkg/bft/consensus/state.go index 4e64418f6ac..a16a9d2f53d 100644 --- a/tm2/pkg/bft/consensus/state.go +++ b/tm2/pkg/bft/consensus/state.go @@ -947,8 +947,15 @@ func (cs *ConsensusState) defaultDecideProposal(height int64, round int) { part := blockParts.GetPart(i) cs.sendInternalMessage(msgInfo{&BlockPartMessage{cs.Height, cs.Round, part}, ""}) } - cs.Logger.Info("Signed proposal", "height", height, "round", round, "proposal", proposal) - cs.Logger.Debug(fmt.Sprintf("Signed proposal block: %v", block)) + + cs.Logger.Info( + "Signed proposal", + "height", height, + "round", round, + "proposal block ID", proposal.BlockID.String(), + "proposal round", proposal.POLRound, + "proposal timestamp", proposal.Timestamp.Unix(), + ) } else if !cs.replayMode { cs.Logger.Error("enterPropose: Error signing proposal", "height", height, "round", round, "err", err) } @@ -1310,9 +1317,13 @@ func (cs *ConsensusState) finalizeCommit(height int64) { panic(fmt.Sprintf("+2/3 committed an invalid block: %v", err)) } - cs.Logger.Info(fmt.Sprintf("Finalizing commit of block with %d txs", block.NumTxs), - "height", block.Height, "hash", block.Hash(), "root", block.AppHash) - cs.Logger.Info(fmt.Sprintf("%v", block)) + cs.Logger.Info( + "Finalizing commit of block", + "root", block.AppHash, + "height", block.Height, + "hash", block.Hash(), + "num txs", block.NumTxs, + ) fail.Fail() // XXX @@ -1415,7 +1426,16 @@ func (cs *ConsensusState) defaultSetProposal(proposal *types.Proposal) error { if cs.ProposalBlockParts == nil { cs.ProposalBlockParts = types.NewPartSetFromHeader(proposal.BlockID.PartsHeader) } - cs.Logger.Info("Received proposal", "proposal", proposal) + + cs.Logger.Info( + "Received proposal", + "height", proposal.Height, + "round", proposal.Round, + "proposal block ID", proposal.BlockID.String(), + "proposal round", proposal.POLRound, + "proposal timestamp", proposal.Timestamp.Unix(), + ) + return nil } @@ -1573,7 +1593,13 @@ func (cs *ConsensusState) addVote(vote *types.Vote, peerID p2p.ID) (added bool, switch vote.Type { case types.PrevoteType: prevotes := cs.Votes.Prevotes(vote.Round) - cs.Logger.Info("Added to prevote", "vote", vote, "prevotes", prevotes.StringShort()) + cs.Logger.Debug( + "Added to prevote", + "type", vote.Type, + "vote height", vote.Height, + "vote round", vote.Round, + "prevotes", prevotes.StringShort(), + ) // If +2/3 prevotes for a block or nil for *any* round: if blockID, ok := prevotes.TwoThirdsMajority(); ok { @@ -1638,7 +1664,13 @@ func (cs *ConsensusState) addVote(vote *types.Vote, peerID p2p.ID) (added bool, case types.PrecommitType: precommits := cs.Votes.Precommits(vote.Round) - cs.Logger.Info("Added to precommit", "vote", vote, "precommits", precommits.StringShort()) + cs.Logger.Debug( + "Added to precommit", + "type", vote.Type, + "vote height", vote.Height, + "vote round", vote.Round, + "precommits", precommits.StringShort(), + ) blockID, ok := precommits.TwoThirdsMajority() if ok { @@ -1713,7 +1745,19 @@ func (cs *ConsensusState) signAddVote(type_ types.SignedMsgType, hash []byte, he vote, err := cs.signVote(type_, hash, header) if err == nil { cs.sendInternalMessage(msgInfo{&VoteMessage{vote}, ""}) - cs.Logger.Info("Signed and pushed vote", "height", cs.Height, "round", cs.Round, "vote", vote, "err", err) + + cs.Logger.Info( + "Signed and pushed vote", + "height", cs.Height, + "round", cs.Round, + "type", vote.Type, + "timestamp", vote.Timestamp.String(), + "height", vote.Height, + "round", vote.Round, + "validator address", vote.ValidatorAddress, + "validator index", vote.ValidatorIndex, + ) + return vote } // if !cs.replayMode { diff --git a/tm2/pkg/p2p/switch.go b/tm2/pkg/p2p/switch.go index 9d013b42ad1..d24240f731e 100644 --- a/tm2/pkg/p2p/switch.go +++ b/tm2/pkg/p2p/switch.go @@ -246,7 +246,12 @@ func (sw *Switch) OnStop() { // NOTE: Broadcast uses goroutines, so order of broadcast may not be preserved. func (sw *Switch) Broadcast(chID byte, msgBytes []byte) chan bool { startTime := time.Now() - sw.Logger.Debug("Broadcast", "channel", chID, "msgBytes", fmt.Sprintf("%X", msgBytes)) + + sw.Logger.Debug( + "Broadcast", + "channel", chID, + "value", fmt.Sprintf("%X", msgBytes), + ) peers := sw.peers.List() var wg sync.WaitGroup