diff --git a/log/logtest/log.go b/log/logtest/log.go index ffdfd1f642..27ea4331d4 100644 --- a/log/logtest/log.go +++ b/log/logtest/log.go @@ -4,6 +4,7 @@ import ( "os" "testing" + "go.uber.org/zap" "go.uber.org/zap/zapcore" "go.uber.org/zap/zaptest" @@ -12,6 +13,10 @@ import ( const testLogLevel = "TEST_LOG_LEVEL" +func Zap(tb testing.TB, override ...zapcore.Level) *zap.Logger { + return New(tb, override...).Zap() +} + // New creates log.Log instance that will use testing.TB.Log internally. func New(tb testing.TB, override ...zapcore.Level) log.Log { var level zapcore.Level diff --git a/log/zap.go b/log/zap.go index 13b85d1d6e..044958d44a 100644 --- a/log/zap.go +++ b/log/zap.go @@ -104,6 +104,10 @@ func ShortStringer(name string, val ShortString) Field { return Field(zap.Stringer(name, shortStringAdapter{val: val})) } +func ZShortStringer(name string, val ShortString) zap.Field { + return zap.Stringer(name, shortStringAdapter{val: val}) +} + // Binary will encode binary content in base64 when logged. func Binary(name string, val []byte) Field { return Field(zap.Binary(name, val)) @@ -183,6 +187,10 @@ func Context(ctx context.Context) Field { return Field(zap.Inline(&marshalledContext{Context: ctx})) } +func ZContext(ctx context.Context) zap.Field { + return zap.Inline(&marshalledContext{Context: ctx}) +} + func Any(key string, value any) Field { return Field(zap.Any(key, value)) } diff --git a/tortoise/algorithm.go b/tortoise/algorithm.go index af0d1b2ac0..4971bcf1d7 100644 --- a/tortoise/algorithm.go +++ b/tortoise/algorithm.go @@ -6,6 +6,8 @@ import ( "sync" "time" + "go.uber.org/zap" + "github.com/spacemeshos/go-spacemesh/common/types" "github.com/spacemeshos/go-spacemesh/common/types/result" "github.com/spacemeshos/go-spacemesh/log" @@ -40,7 +42,7 @@ func DefaultConfig() Config { // Tortoise is a thread safe verifying tortoise wrapper, it just locks all actions. type Tortoise struct { - logger log.Log + logger *zap.Logger ctx context.Context cfg Config @@ -55,7 +57,7 @@ type Opt func(t *Tortoise) // WithLogger defines logger for tortoise. func WithLogger(logger log.Log) Opt { return func(t *Tortoise) { - t.logger = logger + t.logger = logger.Zap() } } @@ -77,16 +79,16 @@ func WithTracer(opts ...TraceOpt) Opt { func New(opts ...Opt) (*Tortoise, error) { t := &Tortoise{ ctx: context.Background(), - logger: log.NewNop(), + logger: log.NewNop().Zap(), cfg: DefaultConfig(), } for _, opt := range opts { opt(t) } if t.cfg.Hdist < t.cfg.Zdist { - t.logger.With().Panic("hdist must be >= zdist", - log.Uint32("hdist", t.cfg.Hdist), - log.Uint32("zdist", t.cfg.Zdist), + t.logger.Panic("hdist must be >= zdist", + zap.Uint32("hdist", t.cfg.Hdist), + zap.Uint32("zdist", t.cfg.Zdist), ) } t.trtl = newTurtle(t.logger, t.cfg) @@ -115,10 +117,10 @@ func (t *Tortoise) LatestComplete() types.LayerID { func (t *Tortoise) OnWeakCoin(lid types.LayerID, coin bool) { t.mu.Lock() defer t.mu.Unlock() - t.logger.With().Debug("on weakcoin", - log.Uint32("layer_id", lid.Uint32()), - log.Uint32("evicted", t.trtl.evicted.Uint32()), - log.Bool("coin", coin), + t.logger.Debug("on weakcoin", + zap.Uint32("layer_id", lid.Uint32()), + zap.Uint32("evicted", t.trtl.evicted.Uint32()), + zap.Bool("coin", coin), ) if lid <= t.trtl.evicted { return @@ -138,10 +140,10 @@ func (t *Tortoise) OnBeacon(eid types.EpochID, beacon types.Beacon) { t.mu.Lock() defer t.mu.Unlock() firstInWindow := t.trtl.evicted.Add(1).GetEpoch() - t.logger.With().Debug("on beacon", - log.Uint32("epoch id", eid.Uint32()), - log.Uint32("first epoch", firstInWindow.Uint32()), - log.Stringer("beacon", beacon), + t.logger.Debug("on beacon", + zap.Uint32("epoch id", eid.Uint32()), + zap.Uint32("first epoch", firstInWindow.Uint32()), + zap.Stringer("beacon", beacon), ) if eid < firstInWindow { return @@ -265,7 +267,9 @@ func (t *Tortoise) OnBallot(ballot *types.BallotTortoiseData) { err := t.trtl.onBallot(ballot) if err != nil { errorsCounter.Inc() - t.logger.With().Error("failed to save state from ballot", ballot.ID, log.Err(err)) + t.logger.Error("failed to save state from ballot", + zap.Stringer("ballot", ballot.ID), + zap.Error(err)) } if t.tracer != nil { t.tracer.On(&BallotTrace{Ballot: ballot}) @@ -383,10 +387,10 @@ func (t *Tortoise) Updates() []result.Layer { } rst, err := t.results(t.trtl.pending, t.trtl.processed) if err != nil { - t.logger.With().Panic("unexpected error", - log.Uint32("pending", t.trtl.pending.Uint32()), - log.Uint32("processed", t.trtl.pending.Uint32()), - log.Err(err), + t.logger.Panic("unexpected error", + zap.Uint32("pending", t.trtl.pending.Uint32()), + zap.Uint32("processed", t.trtl.pending.Uint32()), + zap.Error(err), ) } t.trtl.pending = 0 diff --git a/tortoise/full.go b/tortoise/full.go index 16021a94cd..3d060f7429 100644 --- a/tortoise/full.go +++ b/tortoise/full.go @@ -3,8 +3,9 @@ package tortoise import ( "time" + "go.uber.org/zap" + "github.com/spacemeshos/go-spacemesh/common/types" - "github.com/spacemeshos/go-spacemesh/log" ) func newFullTortoise(config Config, state *state) *full { @@ -29,7 +30,7 @@ type full struct { delayed map[types.LayerID][]*ballotInfo } -func (f *full) countBallot(logger log.Log, ballot *ballotInfo) { +func (f *full) countBallot(logger *zap.Logger, ballot *ballotInfo) { start := time.Now() if f.shouldBeDelayed(logger, ballot) { return @@ -58,13 +59,6 @@ func (f *full) countBallot(logger log.Log, ballot *ballotInfo) { case against: block.margin = block.margin.Sub(ballot.weight) } - logger.With().Debug("counted votes from ballot", - log.Stringer("id", ballot.id), - log.Uint32("lid", ballot.layer.Uint32()), - log.Stringer("block", block.id), - log.Stringer("vote", vote), - log.Stringer("margin", block.margin), - ) } if empty { layer.empty = layer.empty.Add(ballot.weight) @@ -96,7 +90,7 @@ func (f *full) countForLateBlock(block *blockInfo) { lateBlockDuration.Observe(float64(time.Since(start).Nanoseconds())) } -func (f *full) countDelayed(logger log.Log, lid types.LayerID) { +func (f *full) countDelayed(logger *zap.Logger, lid types.LayerID) { delayed, exist := f.delayed[lid] if !exist { return @@ -104,11 +98,11 @@ func (f *full) countDelayed(logger log.Log, lid types.LayerID) { delete(f.delayed, lid) for _, ballot := range delayed { delayedBallots.Dec() - f.countBallot(logger.WithFields(log.Bool("delayed", true)), ballot) + f.countBallot(logger, ballot) } } -func (f *full) countVotes(logger log.Log) { +func (f *full) countVotes(logger *zap.Logger) { for lid := f.counted.Add(1); !lid.After(f.processed); lid = lid.Add(1) { for _, ballot := range f.ballots[lid] { f.countBallot(logger, ballot) @@ -117,32 +111,28 @@ func (f *full) countVotes(logger log.Log) { f.counted = f.processed } -func (f *full) verify(logger log.Log, lid types.LayerID) bool { +func (f *full) verify(logger *zap.Logger, lid types.LayerID) bool { threshold := f.globalThreshold(f.Config, lid) layer := f.state.layer(lid) empty := crossesThreshold(layer.empty, threshold) == support - logger = logger.WithFields( - log.String("verifier", "full"), - log.Stringer("counted layer", f.counted), - log.Stringer("candidate layer", lid), - log.Stringer("local threshold", f.localThreshold), - log.Stringer("global threshold", threshold), - log.Stringer("empty weight", layer.empty), - log.Bool("is empty", empty), - ) if len(layer.blocks) == 0 { if empty { - logger.With().Debug("candidate layer is empty") + logger.Debug("candidate layer is empty", + zap.Uint32("candidate layer", lid.Uint32()), + zap.Float64("global threshold", threshold.Float()), + zap.Float64("empty weight", layer.empty.Float()), + ) } else { - logger.With().Debug("margin is too low to terminate layer as empty", - lid, - log.Stringer("margin", layer.empty), + logger.Debug("margin is too low to terminate layer as empty", + zap.Uint32("candidate layer", lid.Uint32()), + zap.Float64("global threshold", threshold.Float()), + zap.Float64("empty weight", layer.empty.Float()), ) } return empty } - return verifyLayer( + rst, changes := verifyLayer( logger, layer.blocks, func(block *blockInfo) sign { @@ -153,9 +143,22 @@ func (f *full) verify(logger log.Log, lid types.LayerID) bool { return decision }, ) + if changes { + logger.Info("candidate layer is verified", + zapBlocks(layer.blocks), + zap.String("verifier", "full"), + zap.Uint32("counted layer", f.counted.Uint32()), + zap.Uint32("candidate layer", lid.Uint32()), + zap.Float64("local threshold", f.localThreshold.Float()), + zap.Float64("global threshold", threshold.Float()), + zap.Float64("empty weight", layer.empty.Float()), + zap.Bool("is empty", empty), + ) + } + return rst } -func (f *full) shouldBeDelayed(logger log.Log, ballot *ballotInfo) bool { +func (f *full) shouldBeDelayed(logger *zap.Logger, ballot *ballotInfo) bool { if !ballot.conditions.badBeacon { return false } @@ -163,10 +166,10 @@ func (f *full) shouldBeDelayed(logger log.Log, ballot *ballotInfo) bool { if !delay.After(f.last) { return false } - logger.With().Debug("ballot is delayed", - log.Stringer("id", ballot.id), - log.Uint32("ballot lid", ballot.layer.Uint32()), - log.Uint32("counted at", delay.Uint32()), + logger.Debug("ballot is delayed", + zap.Stringer("id", ballot.id), + zap.Uint32("ballot lid", ballot.layer.Uint32()), + zap.Uint32("counted at", delay.Uint32()), ) delayedBallots.Inc() f.delayed[delay] = append(f.delayed[delay], ballot) diff --git a/tortoise/full_test.go b/tortoise/full_test.go index 9bf576bf98..18920cc448 100644 --- a/tortoise/full_test.go +++ b/tortoise/full_test.go @@ -61,7 +61,7 @@ func TestFullBallotFilter(t *testing.T) { config := Config{} config.BadBeaconVoteDelayLayers = tc.distance require.Equal(t, tc.expect, newFullTortoise(config, state).shouldBeDelayed( - logtest.New(t), &tc.ballot)) + logtest.Zap(t), &tc.ballot)) }) } } @@ -321,7 +321,7 @@ func TestFullCountVotes(t *testing.T) { } { tc := tc t.Run(tc.desc, func(t *testing.T) { - logger := logtest.New(t) + logger := logtest.Zap(t) tortoise := defaultAlgorithm(t) var activeset []types.ATXID for i := range tc.activeset { @@ -544,7 +544,7 @@ func TestFullVerify(t *testing.T) { } layer.blocks = append(layer.blocks, block) } - require.Equal(t, tc.validity != nil, full.verify(logtest.New(t), target)) + require.Equal(t, tc.validity != nil, full.verify(logtest.Zap(t), target)) if tc.validity != nil { for i, expect := range tc.validity { require.Equal(t, expect, layer.blocks[i].validity) diff --git a/tortoise/tortoise.go b/tortoise/tortoise.go index a9f08af31b..e7d31f19aa 100644 --- a/tortoise/tortoise.go +++ b/tortoise/tortoise.go @@ -10,6 +10,7 @@ import ( "time" "github.com/spacemeshos/fixed" + "go.uber.org/zap" "github.com/spacemeshos/go-spacemesh/common/types" "github.com/spacemeshos/go-spacemesh/log" @@ -21,7 +22,7 @@ var errBeaconUnavailable = errors.New("beacon unavailable") type turtle struct { Config - logger log.Log + logger *zap.Logger *state @@ -41,7 +42,7 @@ type turtle struct { } // newTurtle creates a new verifying tortoise algorithm instance. -func newTurtle(logger log.Log, config Config) *turtle { +func newTurtle(logger *zap.Logger, config Config) *turtle { t := &turtle{ Config: config, state: newState(), @@ -84,10 +85,10 @@ func (t *turtle) evict(ctx context.Context) { if !ok { return } - t.logger.With().Debug("evict in memory state", - log.Stringer("pending", t.pending), - log.Stringer("from_layer", t.evicted.Add(1)), - log.Stringer("upto_layer", windowStart), + t.logger.Debug("evict in memory state", + zap.Stringer("pending", t.pending), + zap.Stringer("from_layer", t.evicted.Add(1)), + zap.Stringer("upto_layer", windowStart), ) if !windowStart.After(t.evicted) { return @@ -128,8 +129,7 @@ func (t *turtle) EncodeVotes(ctx context.Context, conf *encodeConf) (*types.Opin return nil, err } var ( - logger = t.logger.WithContext(ctx) - err error + err error current = t.last.Add(1) ) @@ -152,18 +152,20 @@ func (t *turtle) EncodeVotes(ctx context.Context, conf *encodeConf) (*types.Opin opinion, err = t.encodeVotes(ctx, base, t.evicted.Add(1), current) if err == nil { metrics.LayerDistanceToBaseBallot.WithLabelValues().Observe(float64(t.last - base.layer)) - logger.With().Info("encoded votes", - log.Stringer("base ballot", base.id), - log.Stringer("base layer", base.layer), - log.Stringer("voting layer", current), - log.Inline(opinion), + t.logger.Info("encoded votes", + log.ZContext(ctx), + zap.Stringer("base ballot", base.id), + zap.Stringer("base layer", base.layer), + zap.Stringer("voting layer", current), + zap.Inline(opinion), ) return opinion, nil } - logger.With().Debug("failed to encode votes using base ballot id", - base.id, - log.Err(err), - log.Stringer("current layer", current), + t.logger.Debug("failed to encode votes using base ballot id", + log.ZContext(ctx), + zap.Stringer("ballot", base.id), + zap.Error(err), + zap.Stringer("current layer", current), ) } } @@ -180,10 +182,6 @@ func (t *turtle) encodeVotes( start types.LayerID, current types.LayerID, ) (*types.Opinion, error) { - logger := t.logger.WithContext(ctx).WithFields( - log.Stringer("base layer", base.layer), - log.Stringer("current layer", current), - ) votes := types.Votes{ Base: base.id, } @@ -197,7 +195,12 @@ func (t *turtle) encodeVotes( return nil, fmt.Errorf("ballot %s can't be used as a base ballot", base.id) } if lvote.vote != abstain && !layer.hareTerminated { - logger.With().Debug("voting abstain on the layer", lvote.lid) + t.logger.Debug("voting abstain on the layer", + log.ZContext(ctx), + zap.Stringer("base layer", base.layer), + zap.Stringer("current layer", current), + zap.Uint32("lid", lvote.lid.Uint32()), + ) votes.Abstain = append(votes.Abstain, lvote.lid) continue } @@ -213,14 +216,26 @@ func (t *turtle) encodeVotes( } switch vote { case support: - logger.With().Debug("support before base ballot", log.Inline(block)) + t.logger.Debug("support before base ballot", + log.ZContext(ctx), + zap.Stringer("base layer", base.layer), + zap.Stringer("current layer", current), + zap.Inline(block)) votes.Support = append(votes.Support, block.header()) case against: - logger.With().Debug("explicit against overwrites base ballot opinion", log.Inline(block)) + t.logger.Debug("explicit against overwrites base ballot opinion", + log.ZContext(ctx), + zap.Stringer("base layer", base.layer), + zap.Stringer("current layer", current), + zap.Inline(block)) votes.Against = append(votes.Against, block.header()) case abstain: - logger.With().Error("layers that are not terminated should have been encoded earlier", - log.Inline(block), log.Stringer("reason", reason), + t.logger.Error("layers that are not terminated should have been encoded earlier", + log.ZContext(ctx), + zap.Stringer("base layer", base.layer), + zap.Stringer("current layer", current), + zap.Inline(block), + zap.Stringer("reason", reason), ) } } @@ -229,7 +244,7 @@ func (t *turtle) encodeVotes( for lid := base.layer; lid.Before(current); lid = lid.Add(1) { layer := t.layer(lid) if !layer.hareTerminated { - logger.With().Debug("voting abstain on the layer", lid) + t.logger.Debug("voting abstain on the layer", zap.Uint32("lid", lid.Uint32())) votes.Abstain = append(votes.Abstain, lid) continue } @@ -240,13 +255,17 @@ func (t *turtle) encodeVotes( } switch vote { case support: - logger.With().Debug("support after base ballot", log.Inline(block), log.Stringer("reason", reason)) + t.logger.Debug("support after base ballot", + log.ZContext(ctx), + zap.Inline(block), + zap.Stringer("reason", reason)) votes.Support = append(votes.Support, block.header()) case against: - logger.With().Debug("implicit against after base ballot", log.Inline(block), log.Stringer("reason", reason)) + t.logger.Debug("implicit against after base ballot", + log.ZContext(ctx), zap.Inline(block), zap.Stringer("reason", reason)) case abstain: - logger.With().Error("layers that are not terminated should have been encoded earlier", - log.Inline(block), log.Stringer("reason", reason), + t.logger.Error("layers that are not terminated should have been encoded earlier", + log.ZContext(ctx), zap.Inline(block), zap.Stringer("reason", reason), ) } } @@ -289,7 +308,7 @@ func (t *turtle) getFullVote(verified, current types.LayerID, block *blockInfo) } func (t *turtle) onLayer(ctx context.Context, last types.LayerID) { - t.logger.With().Debug("on layer", last) + t.logger.Debug("on layer", zap.Uint32("last", last.Uint32())) defer t.evict(ctx) if last.After(t.last) { t.last = last @@ -316,7 +335,7 @@ func (t *turtle) onLayer(ctx context.Context, last types.LayerID) { t.full.counted = process } for _, ballot := range t.ballots[process] { - if err := t.countBallot(t.logger, ballot); err != nil { + if err := t.countBallot(ballot); err != nil { if errors.Is(err, errBeaconUnavailable) { t.retryLater(ballot) } else { @@ -332,9 +351,9 @@ func (t *turtle) onLayer(ctx context.Context, last types.LayerID) { t.pending = types.MinLayer(t.pending, t.last) } - t.logger.With().Debug("initial local opinion", - layer.lid, - log.Stringer("local opinion", layer.opinion)) + t.logger.Debug("initial local opinion", + zap.Uint32("lid", layer.lid.Uint32()), + zap.Stringer("local opinion", layer.opinion)) // terminate layer that falls out of the zdist window and wasn't terminated // by any other component @@ -348,59 +367,56 @@ func (t *turtle) onLayer(ctx context.Context, last types.LayerID) { t.verifyLayers() } -func (t *turtle) switchModes(logger log.Log) { +func (t *turtle) switchModes() { t.isFull = !t.isFull if t.isFull { modeGauge.Set(1) } else { modeGauge.Set(0) } - logger.With().Debug("switching tortoise mode", - log.Uint32("hdist", t.Hdist), - log.Stringer("processed_layer", t.processed), - log.Stringer("verified_layer", t.verified), - log.Bool("is full", t.isFull), + t.logger.Debug("switching tortoise mode", + zap.Uint32("last", t.last.Uint32()), + zap.Uint32("hdist", t.Hdist), + zap.Stringer("processed_layer", t.processed), + zap.Stringer("verified_layer", t.verified), + zap.Bool("is full", t.isFull), ) } -func (t *turtle) countBallot(logger log.Log, ballot *ballotInfo) error { - bad, err := t.compareBeacons(t.logger, ballot.id, ballot.layer, ballot.reference.beacon) +func (t *turtle) countBallot(ballot *ballotInfo) error { + bad, err := t.compareBeacons(ballot.id, ballot.layer, ballot.reference.beacon) if err != nil { return fmt.Errorf("%w: %s", errBeaconUnavailable, err.Error()) } ballot.conditions.badBeacon = bad - t.verifying.countBallot(logger, ballot) + t.verifying.countBallot(t.logger, ballot) if !ballot.layer.After(t.full.counted) { - t.full.countBallot(logger, ballot) + t.full.countBallot(t.logger, ballot) } return nil } func (t *turtle) verifyLayers() { // TODO(dshulyak) simplify processing of layers and notifications - var ( - logger = t.logger.WithFields( - log.Stringer("last layer", t.last), - ) - verified = maxLayer(t.evicted, types.GetEffectiveGenesis()) - ) + verified := maxLayer(t.evicted, types.GetEffectiveGenesis()) + for target := t.evicted.Add(1); target.Before(t.processed); target = target.Add(1) { - success := t.verifying.verify(logger, target) + success := t.verifying.verify(t.logger, target) if success && t.isFull { - t.switchModes(logger) + t.switchModes() } if !success && (t.isFull || !withinDistance(t.Hdist, target, t.last)) { if !t.isFull { - t.switchModes(logger) + t.switchModes() for counted := maxLayer(t.full.counted.Add(1), t.evicted.Add(1)); !counted.After(t.processed); counted = counted.Add(1) { for _, ballot := range t.ballots[counted] { - t.full.countBallot(logger, ballot) + t.full.countBallot(t.logger, ballot) } - t.full.countDelayed(logger, counted) + t.full.countDelayed(t.logger, counted) t.full.counted = counted } } - success = t.full.verify(logger, target) + success = t.full.verify(t.logger, target) } layer := t.layer(target) @@ -437,12 +453,17 @@ func (t *turtle) verifyLayers() { t.changedOpinion.max = types.MaxLayer(t.changedOpinion.max, target) } if block.validity == abstain { - logger.With().Fatal("bug: layer should not be verified if there is an undecided block", target, block.id) + t.logger.Fatal("bug: layer should not be verified if there is an undecided block", + zap.Uint32("target", target.Uint32()), + zap.Stringer("block", block.id)) } - logger.With().Debug("update validity", block.layer, block.id, - log.Stringer("validity", block.validity), - log.Stringer("hare", block.hare), - log.Stringer("emitted", block.emitted), + t.logger.Debug("update validity", + zap.Stringer("last layer", t.last), + zap.Uint32("lid", block.layer.Uint32()), + zap.Stringer("block", block.id), + zap.Stringer("validity", block.validity), + zap.Stringer("hare", block.hare), + zap.Stringer("emitted", block.emitted), ) block.emitted = block.validity } @@ -450,7 +471,11 @@ func (t *turtle) verifyLayers() { t.verified = verified verifiedLayer.Set(float64(t.verified)) if t.changedOpinion.min != 0 && !withinDistance(t.Hdist, t.changedOpinion.max, t.last) { - logger.With().Debug("changed opinion outside hdist", log.Stringer("from", t.changedOpinion.min), log.Stringer("to", t.changedOpinion.max)) + t.logger.Debug("changed opinion outside hdist", + zap.Stringer("last layer", t.last), + zap.Stringer("from", t.changedOpinion.min), + zap.Stringer("to", t.changedOpinion.max), + ) t.onOpinionChange(t.changedOpinion.min) t.changedOpinion.min = 0 t.changedOpinion.max = 0 @@ -477,7 +502,7 @@ func (t *turtle) onBlock(header types.BlockHeader, data bool, valid bool) { } return } - t.logger.With().Debug("on data block", log.Inline(&header)) + t.logger.Debug("on data block", zap.Inline(&header)) binfo := newBlockInfo(header) binfo.data = data @@ -504,7 +529,14 @@ func (t *turtle) onHareOutput(lid types.LayerID, bid types.BlockID) { previous types.BlockID exists bool ) - t.logger.With().Debug("on hare output", lid, bid, log.Bool("empty", bid == types.EmptyBlockID), log.Uint32("processed", t.processed.Uint32()), log.Uint32("hdist", t.Hdist), log.Uint32("last", t.last.Uint32())) + t.logger.Debug("on hare output", + zap.Uint32("lid", lid.Uint32()), + zap.Stringer("block", bid), + zap.Bool("empty", bid == types.EmptyBlockID), + zap.Uint32("processed", t.processed.Uint32()), + zap.Uint32("hdist", t.Hdist), + zap.Uint32("last", t.last.Uint32()), + ) layer.hareTerminated = true for i := range layer.blocks { block := layer.blocks[i] @@ -522,11 +554,11 @@ func (t *turtle) onHareOutput(lid types.LayerID, bid types.BlockID) { return } if !lid.After(t.processed) && withinDistance(t.Config.Hdist, lid, t.last) { - t.logger.With().Debug("local opinion changed within hdist", - lid, - log.Stringer("verified", t.verified), - log.Stringer("previous", previous), - log.Stringer("new", bid), + t.logger.Debug("local opinion changed within hdist", + zap.Uint32("lid", lid.Uint32()), + zap.Stringer("verified", t.verified), + zap.Stringer("previous", previous), + zap.Stringer("new", bid), ) t.onOpinionChange(lid) } @@ -541,9 +573,9 @@ func (t *turtle) onOpinionChange(lid types.LayerID) { if opinion != layer.opinion { t.pending = types.MinLayer(t.pending, lid) } - t.logger.With().Debug("computed local opinion", - layer.lid, - log.Stringer("local opinion", layer.opinion)) + t.logger.Debug("computed local opinion", + zap.Uint32("lid", layer.lid.Uint32()), + zap.Stringer("local opinion", layer.opinion)) } t.verifying.resetWeights(lid) for target := lid.Add(1); !target.After(t.processed); target = target.Add(1) { @@ -555,16 +587,16 @@ func (t *turtle) onAtx(atx *types.AtxTortoiseData) { start := time.Now() epoch := t.epoch(atx.TargetEpoch) if _, exist := epoch.atxs[atx.ID]; !exist { - t.logger.With().Debug("on atx", - log.Stringer("id", atx.ID), - log.Uint32("epoch", uint32(atx.TargetEpoch)), - log.Uint64("weight", atx.Weight), - log.Uint64("height", atx.Height), + t.logger.Debug("on atx", + zap.Stringer("id", atx.ID), + zap.Uint32("epoch", uint32(atx.TargetEpoch)), + zap.Uint64("weight", atx.Weight), + zap.Uint64("height", atx.Height), ) epoch.atxs[atx.ID] = atxInfo{weight: atx.Weight, height: atx.Height} if atx.Weight > math.MaxInt64 { // atx weight is not expected to overflow int64 - t.logger.With().Fatal("fixme: atx size overflows int64", log.Uint64("weight", atx.Weight)) + t.logger.Fatal("fixme: atx size overflows int64", zap.Uint64("weight", atx.Weight)) } epoch.weight = epoch.weight.Add(fixed.New64(int64(atx.Weight))) atxsNumber.Inc() @@ -587,9 +619,9 @@ func (t *turtle) decodeBallot(ballot *types.BallotTortoiseData) (*ballotInfo, ty return nil, 0, nil } - t.logger.With().Debug("on ballot", - log.Inline(ballot), - log.Uint32("processed", t.processed.Uint32()), + t.logger.Debug("on ballot", + zap.Inline(ballot), + zap.Uint32("processed", t.processed.Uint32()), ) var ( @@ -602,8 +634,8 @@ func (t *turtle) decodeBallot(ballot *types.BallotTortoiseData) (*ballotInfo, ty } else { base = t.state.ballotRefs[ballot.Opinion.Votes.Base] if base == nil { - t.logger.With().Warning("base ballot not in state", - log.Stringer("base", ballot.Opinion.Votes.Base), + t.logger.Warn("base ballot not in state", + zap.Stringer("base", ballot.Opinion.Votes.Base), ) return nil, 0, nil } @@ -636,8 +668,8 @@ func (t *turtle) decodeBallot(ballot *types.BallotTortoiseData) (*ballotInfo, ty ptr := *ballot.Ref ref, exists := t.state.ballotRefs[ptr] if !exists { - t.logger.With().Warning("ref ballot not in state", - log.Stringer("ref", ptr), + t.logger.Warn("ref ballot not in state", + zap.Stringer("ref", ptr), ) return nil, 0, nil } @@ -666,14 +698,16 @@ func (t *turtle) decodeBallot(ballot *types.BallotTortoiseData) (*ballotInfo, ty ).Mul(fixed.New(int(ballot.Eligibilities))) } else { binfo.malicious = true - t.logger.With().Warning("ballot from malicious identity will have zeroed weight", ballot.Layer, ballot.ID) + t.logger.Warn("ballot from malicious identity will have zeroed weight", + zap.Uint32("lid", ballot.Layer.Uint32()), + zap.Stringer("ballot", ballot.ID)) } - t.logger.With().Debug("computed weight and height for ballot", - ballot.ID, - log.Stringer("weight", binfo.weight), - log.Uint64("height", refinfo.height), - log.Uint32("lid", ballot.Layer.Uint32()), + t.logger.Debug("computed weight and height for ballot", + zap.Stringer("ballot", ballot.ID), + zap.Stringer("weight", binfo.weight), + zap.Uint64("height", refinfo.height), + zap.Uint32("lid", ballot.Layer.Uint32()), ) votes, min, err := decodeVotes(t.evicted, binfo.layer, base, ballot.Opinion.Votes) @@ -681,9 +715,10 @@ func (t *turtle) decodeBallot(ballot *types.BallotTortoiseData) (*ballotInfo, ty return nil, 0, err } binfo.votes = votes - t.logger.With().Debug("decoded exceptions", - binfo.id, binfo.layer, - log.Stringer("opinion", binfo.opinion()), + t.logger.Debug("decoded exceptions", + zap.Stringer("block", binfo.id), + zap.Uint32("lid", binfo.layer.Uint32()), + zap.Stringer("opinion", binfo.opinion()), ) decodeBallotDuration.Observe(float64(time.Since(start).Nanoseconds())) return binfo, min, nil @@ -706,11 +741,11 @@ func (t *turtle) storeBallot(ballot *ballotInfo, min types.LayerID) { } } if !ballot.layer.After(t.processed) { - if err := t.countBallot(t.logger, ballot); err != nil { + if err := t.countBallot(ballot); err != nil { if errors.Is(err, errBeaconUnavailable) { t.retryLater(ballot) } else { - t.logger.Panic("unexpected error in counting ballots", log.Err(err)) + t.logger.Panic("unexpected error in counting ballots", zap.Error(err)) } } } @@ -725,17 +760,17 @@ func (t *turtle) onBallot(ballot *types.BallotTortoiseData) error { return nil } -func (t *turtle) compareBeacons(logger log.Log, bid types.BallotID, lid types.LayerID, beacon types.Beacon) (bool, error) { +func (t *turtle) compareBeacons(bid types.BallotID, lid types.LayerID, beacon types.Beacon) (bool, error) { epoch := t.epoch(lid.GetEpoch()) if epoch.beacon == nil { return false, errBeaconUnavailable } if beacon != *epoch.beacon { - logger.With().Debug("ballot has different beacon", - log.Uint32("layer_id", lid.Uint32()), - log.Stringer("block", bid), - log.ShortStringer("ballot_beacon", beacon), - log.ShortStringer("epoch_beacon", epoch.beacon), + t.logger.Debug("ballot has different beacon", + zap.Uint32("layer_id", lid.Uint32()), + zap.Stringer("block", bid), + log.ZShortStringer("ballot_beacon", beacon), + log.ZShortStringer("epoch_beacon", epoch.beacon), ) return true, nil } @@ -748,7 +783,7 @@ func (t *turtle) retryLater(ballot *ballotInfo) { func (t *turtle) drainRetriable() error { for front := t.retriable.Front(); front != nil; { - if err := t.countBallot(t.logger, front.Value.(*ballotInfo)); err != nil { + if err := t.countBallot(front.Value.(*ballotInfo)); err != nil { // if beacon is still unavailable - exit and wait for the next call // to drain this queue if errors.Is(err, errBeaconUnavailable) { diff --git a/tortoise/tortoise_test.go b/tortoise/tortoise_test.go index 5b7f02e750..e2ecded4d8 100644 --- a/tortoise/tortoise_test.go +++ b/tortoise/tortoise_test.go @@ -771,16 +771,15 @@ func TestBallotHasGoodBeacon(t *testing.T) { trtl := defaultAlgorithm(t) - logger := logtest.New(t) trtl.OnBeacon(layerID.GetEpoch(), epochBeacon) - badBeacon, err := trtl.trtl.compareBeacons(logger, ballot.ID(), ballot.Layer, epochBeacon) + badBeacon, err := trtl.trtl.compareBeacons(ballot.ID(), ballot.Layer, epochBeacon) assert.NoError(t, err) assert.False(t, badBeacon) // bad beacon beacon := types.RandomBeacon() require.NotEqual(t, epochBeacon, beacon) - badBeacon, err = trtl.trtl.compareBeacons(logger, ballot.ID(), ballot.Layer, beacon) + badBeacon, err = trtl.trtl.compareBeacons(ballot.ID(), ballot.Layer, beacon) assert.NoError(t, err) assert.True(t, badBeacon) } diff --git a/tortoise/util.go b/tortoise/util.go index f7e906c106..ff8e1a606f 100644 --- a/tortoise/util.go +++ b/tortoise/util.go @@ -3,8 +3,10 @@ package tortoise import ( "sort" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "github.com/spacemeshos/go-spacemesh/common/types" - "github.com/spacemeshos/go-spacemesh/log" ) const ( @@ -51,7 +53,7 @@ func maxLayer(i, j types.LayerID) types.LayerID { return j } -func verifyLayer(logger log.Log, blocks []*blockInfo, getDecision func(*blockInfo) sign) bool { +func verifyLayer(logger *zap.Logger, blocks []*blockInfo, getDecision func(*blockInfo) sign) (bool, bool) { // order blocks by height in ascending order // if there is a support before any abstain // and a previous height is lower than the current one @@ -67,13 +69,13 @@ func verifyLayer(logger log.Log, blocks []*blockInfo, getDecision func(*blockInf ) for i, block := range blocks { decision := getDecision(block) - logger.With().Debug("decision for a block", - log.Int("ith", i), - block.id, - block.layer, - log.Stringer("decision", decision), - log.Stringer("weight", block.margin), - log.Uint64("height", block.height), + logger.Debug("decision for a block", + zap.Int("ith", i), + zap.Stringer("block", block.id), + zap.Stringer("lid", block.layer), + zap.Stringer("decision", decision), + zap.Stringer("weight", block.margin), + zap.Uint64("height", block.height), ) if decision == abstain { @@ -81,7 +83,7 @@ func verifyLayer(logger log.Log, blocks []*blockInfo, getDecision func(*blockInf if supported != nil && block.height > supported.height { decision = against } else { - return false + return false, false } } else if decision == support { supported = block @@ -95,23 +97,21 @@ func verifyLayer(logger log.Log, blocks []*blockInfo, getDecision func(*blockInf } blocks[i].validity = decision } - if changes { - logger.With().Info("candidate layer is verified", - log.Array("blocks", - log.ArrayMarshalerFunc(func(encoder log.ArrayEncoder) error { - for i := range blocks { - encoder.AppendObject(log.ObjectMarshallerFunc(func(encoder log.ObjectEncoder) error { - encoder.AddString("decision", blocks[i].validity.String()) - encoder.AddString("id", blocks[i].id.String()) - encoder.AddString("weight", blocks[i].margin.String()) - encoder.AddUint64("height", blocks[i].height) - encoder.AddBool("data", blocks[i].data) - return nil - })) - } - return nil - })), - ) - } - return true + return true, changes +} + +func zapBlocks(blocks []*blockInfo) zap.Field { + return zap.Array("blocks", zapcore.ArrayMarshalerFunc(func(encoder zapcore.ArrayEncoder) error { + for i := range blocks { + encoder.AppendObject(zapcore.ObjectMarshalerFunc(func(encoder zapcore.ObjectEncoder) error { + encoder.AddString("decision", blocks[i].validity.String()) + encoder.AddString("id", blocks[i].id.String()) + encoder.AddString("weight", blocks[i].margin.String()) + encoder.AddUint64("height", blocks[i].height) + encoder.AddBool("data", blocks[i].data) + return nil + })) + } + return nil + })) } diff --git a/tortoise/verifying.go b/tortoise/verifying.go index 4fc4096e71..ed6b45a6cd 100644 --- a/tortoise/verifying.go +++ b/tortoise/verifying.go @@ -3,6 +3,8 @@ package tortoise import ( "time" + "go.uber.org/zap" + "github.com/spacemeshos/go-spacemesh/common/types" "github.com/spacemeshos/go-spacemesh/log" ) @@ -32,23 +34,23 @@ func (v *verifying) resetWeights(voted types.LayerID) { } } -func (v *verifying) countBallot(logger log.Log, ballot *ballotInfo) { +func (v *verifying) countBallot(logger *zap.Logger, ballot *ballotInfo) { start := time.Now() prev := v.layer(ballot.layer.Sub(1)) counted := !(ballot.conditions.badBeacon || prev.opinion != ballot.opinion() || prev.verifying.referenceHeight > ballot.reference.height) - logger.With().Debug("count ballot in verifying mode", - ballot.layer, - ballot.id, - log.ShortStringer("ballot opinion", ballot.opinion()), - log.ShortStringer("local opinion", prev.opinion), - log.Bool("bad beacon", ballot.conditions.badBeacon), - log.Stringer("weight", ballot.weight), - log.Uint64("reference height", prev.verifying.referenceHeight), - log.Uint64("ballot height", ballot.reference.height), - log.Bool("counted", counted), + logger.Debug("count ballot in verifying mode", + zap.Uint32("lid", ballot.layer.Uint32()), + zap.Stringer("ballot", ballot.id), + log.ZShortStringer("ballot opinion", ballot.opinion()), + log.ZShortStringer("local opinion", prev.opinion), + zap.Bool("bad beacon", ballot.conditions.badBeacon), + zap.Float64("weight", ballot.weight.Float()), + zap.Uint64("reference height", prev.verifying.referenceHeight), + zap.Uint64("ballot height", ballot.reference.height), + zap.Bool("counted", counted), ) if !counted { return @@ -62,16 +64,16 @@ func (v *verifying) countBallot(logger log.Log, ballot *ballotInfo) { vcountBallotDuration.Observe(float64(time.Since(start).Nanoseconds())) } -func (v *verifying) countVotes(logger log.Log, ballots []*ballotInfo) { +func (v *verifying) countVotes(logger *zap.Logger, ballots []*ballotInfo) { for _, ballot := range ballots { v.countBallot(logger, ballot) } } -func (v *verifying) verify(logger log.Log, lid types.LayerID) bool { +func (v *verifying) verify(logger *zap.Logger, lid types.LayerID) bool { layer := v.layer(lid) if !layer.hareTerminated { - logger.With().Debug("hare is not terminated") + logger.Debug("hare is not terminated") return false } @@ -85,25 +87,28 @@ func (v *verifying) verify(logger log.Log, lid types.LayerID) bool { } threshold := v.globalThreshold(v.Config, lid) - logger = logger.WithFields( - log.String("verifier", "verifying"), - log.Stringer("candidate layer", lid), - log.Stringer("margin", margin), - log.Stringer("uncounted", uncounted), - log.Stringer("total good weight", v.totalGoodWeight), - log.Stringer("good uncounted", layer.verifying.goodUncounted), - log.Stringer("global threshold", threshold), - ) if crossesThreshold(margin, threshold) != support { - logger.With().Debug("doesn't cross global threshold") + logger.Debug("doesn't cross global threshold", + zap.Uint32("candidate layer", lid.Uint32()), + zap.Float64("margin", margin.Float()), + zap.Float64("global threshold", threshold.Float()), + ) return false } else { - logger.With().Debug("crosses global threshold") + logger.Debug("crosses global threshold", + zap.Uint32("candidate layer", lid.Uint32()), + zap.Float64("margin", margin.Float()), + zap.Float64("global threshold", threshold.Float()), + ) } if len(layer.blocks) == 0 { - logger.With().Debug("candidate layer is empty") + logger.Debug("candidate layer is empty", + zap.Uint32("candidate layer", lid.Uint32()), + zap.Float64("margin", margin.Float()), + zap.Float64("global threshold", threshold.Float()), + ) } - return verifyLayer( + rst, changes := verifyLayer( logger, layer.blocks, func(block *blockInfo) sign { @@ -114,4 +119,17 @@ func (v *verifying) verify(logger log.Log, lid types.LayerID) bool { return decision }, ) + if changes { + logger.Info("candidate layer is verified", + zapBlocks(layer.blocks), + zap.String("verifier", "verifying"), + zap.Uint32("candidate layer", lid.Uint32()), + zap.Float64("margin", margin.Float()), + zap.Float64("global threshold", threshold.Float()), + zap.Float64("uncounted", uncounted.Float()), + zap.Float64("total good weight", v.totalGoodWeight.Float()), + zap.Float64("good uncounted", layer.verifying.goodUncounted.Float()), + ) + } + return rst } diff --git a/tortoise/verifying_test.go b/tortoise/verifying_test.go index 8c8ad9a8ee..f6b10bd21e 100644 --- a/tortoise/verifying_test.go +++ b/tortoise/verifying_test.go @@ -116,7 +116,7 @@ func TestVerifyingProcessLayer(t *testing.T) { } { tc := tc t.Run(tc.desc, func(t *testing.T) { - logger := logtest.New(t) + logger := logtest.Zap(t) v := newVerifying(Config{}, newState()) v.processed = start.Add(1).Add(uint32(len(tc.ballots))) @@ -577,7 +577,7 @@ func TestVerifying_Verify(t *testing.T) { } { tc := tc t.Run(tc.desc, func(t *testing.T) { - logger := logtest.New(t) + logger := logtest.Zap(t) state := newState() state.epochs = epochs