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)


<details><summary>Contributors' checklist...</summary>

- [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).
</details>

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

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?

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)

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
 }

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 {

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