From ebe900958e2a81c590dde15a4bec0270f4684a07 Mon Sep 17 00:00:00 2001 From: Milos Zivkovic Date: Thu, 11 Apr 2024 15:51:23 +0200 Subject: [PATCH 1/4] Slighly improve log lines --- gno.land/cmd/gnoland/start.go | 13 +++++-- gno.land/pkg/gnoland/app.go | 13 +++---- gno.land/pkg/sdk/vm/keeper.go | 8 ++--- tm2/pkg/bft/consensus/state.go | 63 +++++++++++++++++++++++++++++----- tm2/pkg/p2p/switch.go | 7 +++- 5 files changed, 80 insertions(+), 24 deletions(-) diff --git a/gno.land/cmd/gnoland/start.go b/gno.land/cmd/gnoland/start.go index 921fcc89640..271dde4e8ab 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,13 @@ func execStart(c *startCfg, io commands.IO) error { } cfg.LocalApp = gnoApp + 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/pkg/gnoland/app.go b/gno.land/pkg/gnoland/app.go index cc15f74134e..a0bed5b8c28 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" @@ -155,18 +154,20 @@ 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))) + ctx.Logger().Error( + "Unable to deliver genesis tx", + "log", res.Log, + "error", res.Error, + "gas-used", res.GasUsed, + ) // NOTE: comment out to ignore. if !skipFailingGenesisTxs { panic(res.Log) } - } else { - ctx.Logger().Info("SUCCESS:", "value", string(amino.MustMarshalJSON(tx))) } } // Done! 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..a978c610d4e 100644 --- a/tm2/pkg/bft/consensus/state.go +++ b/tm2/pkg/bft/consensus/state.go @@ -947,8 +947,16 @@ 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 +1318,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 +1427,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 +1594,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 +1665,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 +1746,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 From 69819c1fb9d60744ad952f7a4ce957104a7355fe Mon Sep 17 00:00:00 2001 From: Milos Zivkovic Date: Thu, 11 Apr 2024 17:19:41 +0200 Subject: [PATCH 2/4] Fix linter --- tm2/pkg/bft/consensus/state.go | 1 - 1 file changed, 1 deletion(-) diff --git a/tm2/pkg/bft/consensus/state.go b/tm2/pkg/bft/consensus/state.go index a978c610d4e..a16a9d2f53d 100644 --- a/tm2/pkg/bft/consensus/state.go +++ b/tm2/pkg/bft/consensus/state.go @@ -956,7 +956,6 @@ func (cs *ConsensusState) defaultDecideProposal(height int64, round int) { "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) } From 3ac6543d86d062f49b6114a67559b3203ff6eb5b Mon Sep 17 00:00:00 2001 From: Milos Zivkovic Date: Fri, 12 Apr 2024 11:31:54 +0200 Subject: [PATCH 3/4] Clean up legacy test --- gno.land/cmd/gnoland/start_test.go | 69 +++++++++++++----------------- 1 file changed, 30 insertions(+), 39 deletions(-) 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? From f554f5fbb29f1d128fbf27c733305110925aede1 Mon Sep 17 00:00:00 2001 From: Milos Zivkovic Date: Tue, 16 Apr 2024 17:50:52 +0200 Subject: [PATCH 4/4] Conditionally print start graphic --- gno.land/cmd/gnoland/start.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/gno.land/cmd/gnoland/start.go b/gno.land/cmd/gnoland/start.go index 271dde4e8ab..a991e2e0dc0 100644 --- a/gno.land/cmd/gnoland/start.go +++ b/gno.land/cmd/gnoland/start.go @@ -277,7 +277,9 @@ func execStart(c *startCfg, io commands.IO) error { } cfg.LocalApp = gnoApp - io.Println(startGraphic) + if logFormat != log.JSONFormat { + io.Println(startGraphic) + } gnoNode, err := node.DefaultNewNode(cfg, logger) if err != nil {