Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Merged by Bors] - use zap in genvm #6236

Closed
wants to merge 2 commits into from
Closed

[Merged by Bors] - use zap in genvm #6236

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
331e930
use zap in genvm
poszu Aug 9, 2024
4682a03
clean up logtest usages
poszu Aug 9, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
11 changes: 5 additions & 6 deletions api/grpcserver/grpcserver_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,6 @@ import (
vm "github.com/spacemeshos/go-spacemesh/genvm"
"github.com/spacemeshos/go-spacemesh/genvm/sdk"
"github.com/spacemeshos/go-spacemesh/genvm/sdk/wallet"
"github.com/spacemeshos/go-spacemesh/log/logtest"
"github.com/spacemeshos/go-spacemesh/p2p"
"github.com/spacemeshos/go-spacemesh/p2p/peerinfo"
peerinfomocks "github.com/spacemeshos/go-spacemesh/p2p/peerinfo/mocks"
Expand Down Expand Up @@ -2272,9 +2271,9 @@ func TestEventsReceived(t *testing.T) {
// Give the server-side time to subscribe to events
time.Sleep(time.Millisecond * 50)

lg := logtest.New(t)
lg := zaptest.NewLogger(t)
svm := vm.New(sql.InMemory(), vm.WithLogger(lg))
conState := txs.NewConservativeState(svm, sql.InMemory(), txs.WithLogger(lg.Zap().Named("conState")))
conState := txs.NewConservativeState(svm, sql.InMemory(), txs.WithLogger(lg.Named("conState")))
conState.AddToCache(context.Background(), globalTx, time.Now())

weight := new(big.Rat).SetFloat64(18.7)
Expand Down Expand Up @@ -2337,7 +2336,7 @@ func TestTransactionsRewards(t *testing.T) {
req.NoError(err, "stream request returned unexpected error")
time.Sleep(50 * time.Millisecond)

svm := vm.New(sql.InMemory(), vm.WithLogger(logtest.New(t)))
svm := vm.New(sql.InMemory(), vm.WithLogger(zaptest.NewLogger(t)))
_, _, err = svm.Apply(vm.ApplyContext{Layer: types.LayerID(17)}, []types.Transaction{*globalTx}, rewards)
req.NoError(err)

Expand All @@ -2358,7 +2357,7 @@ func TestTransactionsRewards(t *testing.T) {
req.NoError(err, "stream request returned unexpected error")
time.Sleep(50 * time.Millisecond)

svm := vm.New(sql.InMemory(), vm.WithLogger(logtest.New(t)))
svm := vm.New(sql.InMemory(), vm.WithLogger(zaptest.NewLogger(t)))
_, _, err = svm.Apply(vm.ApplyContext{Layer: types.LayerID(17)}, []types.Transaction{*globalTx}, rewards)
req.NoError(err)

Expand All @@ -2380,7 +2379,7 @@ func TestVMAccountUpdates(t *testing.T) {
db, err := sql.Open("file:" + filepath.Join(t.TempDir(), "test.sql"))
require.NoError(t, err)
t.Cleanup(func() { db.Close() })
svm := vm.New(db, vm.WithLogger(logtest.New(t)))
svm := vm.New(db, vm.WithLogger(zaptest.NewLogger(t)))
cfg, cleanup := launchServer(t, NewGlobalStateService(nil, txs.NewConservativeState(svm, db)))
t.Cleanup(cleanup)

Expand Down
30 changes: 15 additions & 15 deletions genvm/rewards.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5,10 +5,10 @@ import (
"math/big"

"github.com/spacemeshos/economics/rewards"
"go.uber.org/zap"

"github.com/spacemeshos/go-spacemesh/common/types"
"github.com/spacemeshos/go-spacemesh/genvm/core"
"github.com/spacemeshos/go-spacemesh/log"
)

func (v *VM) addRewards(
Expand Down Expand Up @@ -50,12 +50,12 @@ func (v *VM) addRewards(
core.ErrInternal, subsidyReward, blockReward.Coinbase)
}

v.logger.With().Debug("rewards for coinbase",
lctx.Layer,
blockReward.Coinbase,
log.Stringer("relative weight", &blockReward.Weight),
log.Uint64("subsidy", subsidyReward.Uint64()),
log.Uint64("total", totalReward.Uint64()),
v.logger.Debug("rewards for coinbase",
zap.Uint32("layer", lctx.Layer.Uint32()),
zap.Stringer("coinbase", blockReward.Coinbase),
zap.Stringer("relative weight", &blockReward.Weight),
zap.Uint64("subsidy", subsidyReward.Uint64()),
zap.Uint64("total", totalReward.Uint64()),
)

reward := types.Reward{
Expand All @@ -76,14 +76,14 @@ func (v *VM) addRewards(
}
transferred += totalReward.Uint64()
}
v.logger.With().Debug("rewards for layer",
lctx.Layer,
log.Uint32("after genesis", layersAfterEffectiveGenesis),
log.Uint64("subsidy estimated", subsidy),
log.Uint64("fee", fees),
log.Uint64("total estimated", total),
log.Uint64("total transferred", transferred),
log.Uint64("total burnt", total-transferred),
v.logger.Debug("rewards for layer",
zap.Uint32("layer", lctx.Layer.Uint32()),
zap.Uint32("after genesis", layersAfterEffectiveGenesis),
zap.Uint64("subsidy estimated", subsidy),
zap.Uint64("fee", fees),
zap.Uint64("total estimated", total),
zap.Uint64("total transferred", transferred),
zap.Uint64("total burnt", total-transferred),
)
feesCount.Add(float64(fees))
subsidyCount.Add(float64(subsidy))
Expand Down
85 changes: 43 additions & 42 deletions genvm/vm.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@
"time"

"github.com/spacemeshos/go-scale"
"go.uber.org/zap"

"github.com/spacemeshos/go-spacemesh/common/types"
"github.com/spacemeshos/go-spacemesh/events"
Expand All @@ -31,7 +32,7 @@
type Opt func(*VM)

// WithLogger sets logger for VM.
func WithLogger(logger log.Log) Opt {
func WithLogger(logger *zap.Logger) Opt {
return func(vm *VM) {
vm.logger = logger
}
Expand Down Expand Up @@ -60,7 +61,7 @@
// New returns VM instance.
func New(db *sql.Database, opts ...Opt) *VM {
vm := &VM{
logger: log.NewNop(),
logger: zap.NewNop(),
db: db,
cfg: DefaultConfig(),
registry: registry.New(),
Expand All @@ -77,7 +78,7 @@

// VM handles modifications to the account state.
type VM struct {
logger log.Log
logger *zap.Logger
db *sql.Database
cfg Config
registry *registry.Registry
Expand Down Expand Up @@ -143,7 +144,7 @@
if err := v.revert(lid); err != nil {
return err
}
v.logger.With().Info("vm reverted to layer", lid)
v.logger.Info("vm reverted to layer", zap.Uint32("layer", lid.Uint32()))

Check warning on line 147 in genvm/vm.go

View check run for this annotation

Codecov / codecov/patch

genvm/vm.go#L147 

Added line #L147 was not covered by tests
return nil
}

Expand Down Expand Up @@ -179,7 +180,7 @@
defer tx.Release()
for i := range genesis {
account := &genesis[i]
v.logger.With().Info("genesis account", log.Inline(account))
v.logger.Info("genesis account", zap.Inline(account))
if err := accounts.Update(tx, account); err != nil {
return fmt.Errorf("inserting genesis account: %w", err)
}
Expand Down Expand Up @@ -236,7 +237,7 @@
ss.IterateChanged(func(account *core.Account) bool {
total++
account.Layer = lctx.Layer
v.logger.With().Debug("update account state", log.Inline(account))
v.logger.Debug("update account state", zap.Inline(account))
err = accounts.Update(tx, account)
if err != nil {
return false
Expand Down Expand Up @@ -271,11 +272,11 @@
transactionsPerBlock.Observe(float64(len(txs)))
appliedLayer.Set(float64(lctx.Layer))

v.logger.With().Debug("applied layer",
log.Uint32("layer", lctx.Layer.Uint32()),
log.Int("count", len(txs)-len(skipped)),
log.Duration("duration", time.Since(t1)),
log.Stringer("state_hash", hashSum),
v.logger.Debug("applied layer",
zap.Uint32("layer", lctx.Layer.Uint32()),
zap.Int("count", len(txs)-len(skipped)),
zap.Duration("duration", time.Since(t1)),
zap.Stringer("state_hash", hashSum),
)
return skipped, results, nil
}
Expand All @@ -294,7 +295,7 @@
limit = v.cfg.GasLimit
)
for i, tx := range txs {
logger := v.logger.WithFields(log.Int("ith", i))
logger := v.logger.With(zap.Int("ith", i))
txCount.Inc()

t1 := time.Now()
Expand All @@ -310,9 +311,9 @@

header, err := req.Parse()
if err != nil {
logger.With().Warning("ineffective transaction. failed to parse",
tx.GetRaw().ID,
log.Err(err),
logger.Warn("ineffective transaction. failed to parse",
log.ZShortStringer("tx", tx.GetRaw().ID),
zap.Error(err),
)
ineffective = append(ineffective, types.Transaction{RawTx: tx.GetRaw()})
invalidTxCount.Inc()
Expand All @@ -322,30 +323,30 @@
args := req.args

if header.GasPrice == 0 {
logger.With().Warning("ineffective transaction. zero gas price",
log.Object("header", header),
log.Object("account", &ctx.PrincipalAccount),
logger.Warn("ineffective transaction. zero gas price",
zap.Object("header", header),
zap.Object("account", &ctx.PrincipalAccount),
)
ineffective = append(ineffective, types.Transaction{RawTx: tx.GetRaw()})
invalidTxCount.Inc()
continue
}
if intrinsic := core.IntrinsicGas(ctx.Gas.BaseGas, tx.GetRaw().Raw); ctx.PrincipalAccount.Balance < intrinsic {
logger.With().Warning("ineffective transaction. intrinsic gas not covered",
log.Object("header", header),
log.Object("account", &ctx.PrincipalAccount),
log.Uint64("intrinsic gas", intrinsic),
logger.Warn("ineffective transaction. intrinsic gas not covered",
zap.Object("header", header),
zap.Object("account", &ctx.PrincipalAccount),
zap.Uint64("intrinsic gas", intrinsic),
)
ineffective = append(ineffective, types.Transaction{RawTx: tx.GetRaw()})
invalidTxCount.Inc()
continue
}
if limit < ctx.Header.MaxGas {
logger.With().Warning("ineffective transaction. out of block gas",
log.Uint64("block gas limit", v.cfg.GasLimit),
log.Uint64("current limit", limit),
log.Object("header", header),
log.Object("account", &ctx.PrincipalAccount),
logger.Warn("ineffective transaction. out of block gas",
zap.Uint64("block gas limit", v.cfg.GasLimit),
zap.Uint64("current limit", limit),
zap.Object("header", header),
zap.Object("account", &ctx.PrincipalAccount),
)
ineffective = append(ineffective, types.Transaction{RawTx: tx.GetRaw()})
invalidTxCount.Inc()
Expand All @@ -355,29 +356,29 @@
// NOTE this part is executed only for transactions that weren't verified
// when saved into database by txs module
if !tx.Verified() && !req.Verify() {
logger.With().Warning("ineffective transaction. failed verify",
log.Object("header", header),
log.Object("account", &ctx.PrincipalAccount),
logger.Warn("ineffective transaction. failed verify",
zap.Object("header", header),
zap.Object("account", &ctx.PrincipalAccount),
)
ineffective = append(ineffective, types.Transaction{RawTx: tx.GetRaw()})
invalidTxCount.Inc()
continue
}

if ctx.PrincipalAccount.NextNonce > ctx.Header.Nonce {
logger.With().Warning("ineffective transaction. nonce too low",
log.Object("header", header),
log.Object("account", &ctx.PrincipalAccount),
logger.Warn("ineffective transaction. nonce too low",
zap.Object("header", header),
zap.Object("account", &ctx.PrincipalAccount),
)
ineffective = append(ineffective, types.Transaction{RawTx: tx.GetRaw(), TxHeader: header})
invalidTxCount.Inc()
continue
}

t2 := time.Now()
logger.With().Debug("applying transaction",
log.Object("header", header),
log.Object("account", &ctx.PrincipalAccount),
logger.Debug("applying transaction",
zap.Object("header", header),
zap.Object("account", &ctx.PrincipalAccount),
)

rst := types.TransactionWithResult{}
Expand All @@ -388,10 +389,10 @@
err = ctx.PrincipalHandler.Exec(ctx, ctx.Header.Method, args)
}
if err != nil {
logger.With().Debug("transaction failed",
log.Object("header", header),
log.Object("account", &ctx.PrincipalAccount),
log.Err(err),
logger.Debug("transaction failed",
zap.Object("header", header),
zap.Object("account", &ctx.PrincipalAccount),
zap.Error(err),
)
if errors.Is(err, core.ErrInternal) {
return nil, nil, 0, err
Expand Down Expand Up @@ -467,7 +468,7 @@
}

func parse(
logger log.Log,
logger *zap.Logger,
lid types.LayerID,
reg *registry.Registry,
loader core.AccountLoader,
Expand Down Expand Up @@ -500,7 +501,7 @@
err,
)
}
logger.With().Debug("loaded account state", log.Inline(&account))
logger.Debug("loaded account state", zap.Inline(&account))

ctx := &core.Context{
GenesisID: cfg.GenesisID,
Expand Down
9 changes: 5 additions & 4 deletions genvm/vm_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@ import (
"github.com/spacemeshos/economics/rewards"
"github.com/spacemeshos/go-scale"
"github.com/stretchr/testify/require"
"go.uber.org/zap/zaptest"

"github.com/spacemeshos/go-spacemesh/codec"
"github.com/spacemeshos/go-spacemesh/common/types"
Expand All @@ -32,7 +33,6 @@ import (
"github.com/spacemeshos/go-spacemesh/genvm/templates/vesting"
"github.com/spacemeshos/go-spacemesh/genvm/templates/wallet"
"github.com/spacemeshos/go-spacemesh/hash"
"github.com/spacemeshos/go-spacemesh/log/logtest"
"github.com/spacemeshos/go-spacemesh/signing"
"github.com/spacemeshos/go-spacemesh/sql"
"github.com/spacemeshos/go-spacemesh/sql/accounts"
Expand All @@ -49,7 +49,7 @@ func newTester(tb testing.TB) *tester {
return &tester{
TB: tb,
VM: New(sql.InMemory(),
WithLogger(logtest.New(tb)),
WithLogger(zaptest.NewLogger(tb)),
WithConfig(Config{GasLimit: math.MaxUint64}),
),
rng: rand.New(rand.NewSource(time.Now().UnixNano())),
Expand Down Expand Up @@ -282,7 +282,7 @@ func (t *tester) persistent() *tester {
db, err := sql.Open("file:" + filepath.Join(t.TempDir(), "test.sql"))
t.Cleanup(func() { require.NoError(t, db.Close()) })
require.NoError(t, err)
t.VM = New(db, WithLogger(logtest.New(t)),
t.VM = New(db, WithLogger(zaptest.NewLogger(t)),
WithConfig(Config{GasLimit: math.MaxUint64}))
return t
}
Expand Down Expand Up @@ -2481,6 +2481,7 @@ func FuzzParse(f *testing.F) {
}
}
f.Fuzz(func(t *testing.T, version int, principal []byte, method int, payload, args, sig []byte) {
tt.VM.logger = zaptest.NewLogger(t)
var (
buf = bytes.NewBuffer(nil)
enc = scale.NewEncoder(buf)
Expand Down Expand Up @@ -2572,7 +2573,7 @@ func TestVestingData(t *testing.T) {
spendAccountNonce := t2.nonces[0]
spendAmount := uint64(1_000_000)

vm := New(sql.InMemory(), WithLogger(logtest.New(t)))
vm := New(sql.InMemory(), WithLogger(zaptest.NewLogger(t)))
require.NoError(t, vm.ApplyGenesis(
[]core.Account{
{
Expand Down
5 changes: 2 additions & 3 deletions hare3/hare_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,6 @@ import (
"github.com/spacemeshos/go-spacemesh/common/types"
"github.com/spacemeshos/go-spacemesh/hare3/eligibility"
"github.com/spacemeshos/go-spacemesh/layerpatrol"
"github.com/spacemeshos/go-spacemesh/log/logtest"
"github.com/spacemeshos/go-spacemesh/p2p/pubsub"
pmocks "github.com/spacemeshos/go-spacemesh/p2p/pubsub/mocks"
"github.com/spacemeshos/go-spacemesh/proposals/store"
Expand Down Expand Up @@ -210,7 +209,7 @@ func (n *node) withPublisher() *node {
}

func (n *node) withHare() *node {
logger := logtest.New(n.t).Named(fmt.Sprintf("hare=%d", n.i))
logger := zaptest.NewLogger(n.t).Named(fmt.Sprintf("hare=%d", n.i))

n.nclock = &testNodeClock{
genesis: n.t.start,
Expand All @@ -230,7 +229,7 @@ func (n *node) withHare() *node {
n.msyncer,
n.patrol,
WithConfig(n.t.cfg),
WithLogger(logger.Zap()),
WithLogger(logger),
WithWallclock(n.clock),
WithTracer(tracer),
)
Expand Down
Loading
Loading