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

Jump to bottom

Clean up logging #5582

Closed
wants to merge 5 commits into from
Closed

Clean up logging #5582

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
9e665b9
Tame logging
lrettig Feb 17, 2024
94e894d
More log cleanup
lrettig Feb 17, 2024
ed566b1
Fix log field
lrettig Feb 17, 2024
fe012fb
Logging tweak
lrettig Feb 19, 2024
f10f46b
Merge branch 'develop' into sync-log-cleanup
lrettig Feb 19, 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
8 changes: 4 additions & 4 deletions activation/handler.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -126,7 +126,7 @@
log.Stringer("smesher", atx.SmesherID),
)
if err := h.ContextuallyValidateAtx(atx); err != nil {
h.log.WithContext(ctx).With().Warning("atx failed contextual validation",
h.log.WithContext(ctx).With().Info("atx failed contextual validation",

Check warning on line 129 in activation/handler.go

View check run for this annotation

Codecov / codecov/patch

activation/handler.go#L129 

Added line #L129 was not covered by tests
atx.ID(),
log.Stringer("smesher", atx.SmesherID),
log.Err(err),
Expand Down Expand Up @@ -269,7 +269,7 @@
return nil, fmt.Errorf("adding malfeasance proof: %w", err)
}
if err := h.publisher.Publish(ctx, pubsub.MalfeasanceProof, codec.MustEncode(&gossip)); err != nil {
h.log.With().Error("failed to broadcast malfeasance proof", log.Err(err))
h.log.With().Error("failed to broadcast malfeasance proof after validating nipost", log.Err(err))

Check warning on line 272 in activation/handler.go

View check run for this annotation

Codecov / codecov/patch

activation/handler.go#L272 

Added line #L272 was not covered by tests
}
h.cdb.CacheMalfeasanceProof(atx.SmesherID, &gossip.MalfeasanceProof)
h.tortoise.OnMalfeasance(atx.SmesherID)
Expand Down Expand Up @@ -454,7 +454,7 @@
return fmt.Errorf("add malfeasance proof: %w", err)
}

h.log.WithContext(ctx).With().Warning("smesher produced more than one atx in the same epoch",
h.log.WithContext(ctx).With().Info("smesher produced more than one atx in the same epoch",
log.Stringer("smesher", atx.SmesherID),
log.Object("prev", prev),
log.Object("curr", atx),
Expand Down Expand Up @@ -493,7 +493,7 @@
h.log.With().Fatal("failed to encode malfeasance gossip", log.Err(err))
}
if err = h.publisher.Publish(ctx, pubsub.MalfeasanceProof, encodedProof); err != nil {
h.log.With().Error("failed to broadcast malfeasance proof", log.Err(err))
h.log.With().Warning("failed to broadcast malfeasance proof after store atx", log.Err(err))

Check warning on line 496 in activation/handler.go

View check run for this annotation

Codecov / codecov/patch

activation/handler.go#L496 

Added line #L496 was not covered by tests
return fmt.Errorf("broadcast atx malfeasance proof: %w", err)
}
return errMaliciousATX
Expand Down
2 changes: 1 addition & 1 deletion activation/poetdb.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -114,7 +114,7 @@ func (db *PoetDb) StoreProof(ctx context.Context, ref types.PoetProofRef, proofM
proofMessage.PoetServiceID[:5], proofMessage.RoundID, err)
}

db.log.WithContext(ctx).With().Info("stored poet proof",
db.log.WithContext(ctx).With().Debug("stored poet proof",
log.String("poet_proof_id", fmt.Sprintf("%x", ref[:5])),
log.String("round_id", proofMessage.RoundID),
log.String("poet_service_id", fmt.Sprintf("%x", proofMessage.PoetServiceID[:5])),
Expand Down
4 changes: 2 additions & 2 deletions api/grpcserver/grpc.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -44,7 +44,7 @@ type Server struct {
}

func unaryGrpcLogStart(ctx context.Context, req any, _ *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (any, error) {
ctxzap.Info(ctx, "started unary call")
ctxzap.Debug(ctx, "started unary call")
return handler(ctx, req)
}

Expand All @@ -54,7 +54,7 @@ func streamingGrpcLogStart(
_ *grpc.StreamServerInfo,
handler grpc.StreamHandler,
) error {
ctxzap.Info(stream.Context(), "started streaming call")
ctxzap.Debug(stream.Context(), "started streaming call")
return handler(srv, stream)
}

Expand Down
2 changes: 1 addition & 1 deletion config/logging.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -55,7 +55,7 @@ func DefaultLoggingConfig() LoggerConfig {
Encoder: ConsoleLogEncoder,
AppLoggerLevel: defaultLoggingLevel.String(),
GrpcLoggerLevel: defaultLoggingLevel.String(),
P2PLoggerLevel: zapcore.WarnLevel.String(),
P2PLoggerLevel: defaultLoggingLevel.String(),
PostLoggerLevel: defaultLoggingLevel.String(),
StateDbLoggerLevel: defaultLoggingLevel.String(),
AtxHandlerLevel: defaultLoggingLevel.String(),
Expand Down
4 changes: 2 additions & 2 deletions fetch/fetch.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -565,7 +565,7 @@ func (f *Fetch) send(requests []RequestMessage) {
go func() {
data, err := f.sendBatch(peer, batch)
if err != nil {
f.logger.With().Warning(
f.logger.With().Debug(
"failed to send batch request",
log.Stringer("batch", batch.ID),
log.Stringer("peer", peer),
Expand Down Expand Up @@ -674,7 +674,7 @@ func (f *Fetch) handleHashError(batch *batchInfo, err error) {
continue
}
f.logger.WithContext(req.ctx).With().
Warning("hash request failed", log.Stringer("hash", req.hash), log.Err(err))
Debug("hash request failed", log.Stringer("hash", req.hash), log.Err(err))
req.promise.err = err
peerErrors.WithLabelValues(string(req.hint)).Inc()
close(req.promise.completed)
Expand Down
5 changes: 4 additions & 1 deletion fetch/mesh_data.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -68,6 +68,8 @@ func (f *Fetch) getHashes(

var eg errgroup.Group
var failed atomic.Uint64
f.logger.WithContext(ctx).With().Info("attempting to fetch hash objects",
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

IMO debug too.

log.Uint64("count", uint64(len(hashes))))
for i, hash := range hashes {
if err := options.limiter.Acquire(ctx, 1); err != nil {
pendingMetric.Add(float64(i - len(hashes)))
Expand Down Expand Up @@ -97,7 +99,7 @@ func (f *Fetch) getHashes(
options.limiter.Release(1)
pendingMetric.Add(-1)
if p.err != nil {
f.logger.Debug("failed to get hash",
f.logger.WithContext(ctx).With().Debug("failed to get hash",
log.String("hint", string(hint)),
log.Stringer("hash", h),
log.Err(p.err),
Expand All @@ -110,6 +112,7 @@ func (f *Fetch) getHashes(
}

eg.Wait()
f.logger.WithContext(ctx).With().Info("finished fetching hash objects")
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

IMO this it debug

if failed.Load() > 0 {
return fmt.Errorf("failed to fetch %d hashes out of %d", failed.Load(), len(hashes))
}
Expand Down
2 changes: 1 addition & 1 deletion miner/proposal_builder.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -387,7 +387,7 @@ func (pb *ProposalBuilder) decideMeshHash(ctx context.Context, current types.Lay
}

func (pb *ProposalBuilder) UpdateActiveSet(epoch types.EpochID, activeSet []types.ATXID) {
pb.logger.With().Info("received activeset update",
pb.logger.With().Debug("received activeset update",
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That one IMO is Info because it's the centralized update.

epoch,
log.Int("size", len(activeSet)),
)
Expand Down
6 changes: 4 additions & 2 deletions node/node.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -559,7 +559,7 @@
return logger.WithName(name)
}

func (app *App) getLevel(name string) log.Level {

Check failure on line 562 in node/node.go

View workflow job for this annotation

GitHub Actions / lint 

func (*App).getLevel is unused (U1000)
alvl, exist := app.loggers[name]
if !exist {
return 0
Expand Down Expand Up @@ -1856,8 +1856,10 @@
cfg := app.Config.P2P
cfg.DataDir = filepath.Join(app.Config.DataDir(), "p2p")
p2plog := app.addLogger(P2PLogger, lg)
// if addLogger won't add a level we will use a default 0 (info).
cfg.LogLevel = app.getLevel(P2PLogger)

// our p2p code logs at the default level (Info), but we want the lower level libp2p logging
// to be less verbose
cfg.LogLevel = zapcore.WarnLevel
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it's configurable; why not change the default config instead? Sometimes we really need to set it.

prologue := fmt.Sprintf("%x-%v",
app.Config.Genesis.GenesisID(),
types.GetEffectiveGenesis(),
Expand Down
6 changes: 3 additions & 3 deletions p2p/dhtdiscovery/discovery.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -300,7 +300,7 @@
}
eg.Go(func() error {
if err := d.h.Connect(conCtx, boot); err != nil {
d.logger.Warn("failed to connect",
d.logger.Debug("failed to connect",

Check warning on line 303 in p2p/dhtdiscovery/discovery.go

View check run for this annotation

Codecov / codecov/patch

p2p/dhtdiscovery/discovery.go#L303 

Added line #L303 was not covered by tests
zap.Stringer("address", boot),
zap.Error(err),
)
Expand Down Expand Up @@ -333,14 +333,14 @@
dht.RoutingTableFilter(dht.PublicRoutingTableFilter))
}
opts = append(opts, dht.Mode(d.mode))
dht, err := dht.New(ctx, d.h, opts...)
myDht, err := dht.New(ctx, d.h, opts...)
if err != nil {
if err := ds.Close(); err != nil {
d.logger.Error("error closing level datastore", zap.Error(err))
}
return err
}
d.dht = dht
d.dht = myDht
d.datastore = ds
return nil
}
Expand Down
4 changes: 2 additions & 2 deletions p2p/upgrade.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -409,7 +409,7 @@
return nil
}
natEv := ev.(event.EvtNATDeviceTypeChanged)
fh.logger.With().Info("NAT type changed",
fh.logger.With().Debug("NAT type changed",

Check warning on line 412 in p2p/upgrade.go

View check run for this annotation

Codecov / codecov/patch

p2p/upgrade.go#L412 

Added line #L412 was not covered by tests
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Will be hard to detect what's wrong when we hide it with Debug.

log.Stringer("transportProtocol", natEv.TransportProtocol),
log.Stringer("type", natEv.NatDeviceType))
fh.natType.Lock()
Expand All @@ -425,7 +425,7 @@
return nil
}
reachEv := ev.(event.EvtLocalReachabilityChanged)
fh.logger.With().Info("local reachability changed",
fh.logger.With().Debug("local reachability changed",

Check warning on line 428 in p2p/upgrade.go

View check run for this annotation

Codecov / codecov/patch

p2p/upgrade.go#L428 

Added line #L428 was not covered by tests
log.Stringer("reachability", reachEv.Reachability))
fh.reachability.Lock()
fh.reachability.value = reachEv.Reachability
Expand Down
2 changes: 1 addition & 1 deletion proposals/handler.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -391,7 +391,7 @@
}
if err = h.publisher.Publish(ctx, pubsub.MalfeasanceProof, encodedProof); err != nil {
failedPublish.Inc()
logger.With().Error("failed to broadcast malfeasance proof", log.Err(err))
logger.With().Error("failed to broadcast malfeasance proof after process ballot", log.Err(err))

Check warning on line 394 in proposals/handler.go

View check run for this annotation

Codecov / codecov/patch

proposals/handler.go#L394 

Added line #L394 was not covered by tests
return fmt.Errorf("broadcast ballot malfeasance proof: %w", err)
}
return errMaliciousBallot
Expand Down
8 changes: 7 additions & 1 deletion syncer/data_fetch.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -310,7 +310,7 @@
return fmt.Errorf("get epoch info (peer %v): %w", peer, err)
}
if len(ed.AtxIDs) == 0 {
d.logger.WithContext(ctx).With().Debug("peer have zero atx",
d.logger.WithContext(ctx).With().Debug("peer has no atx data",

Check warning on line 313 in syncer/data_fetch.go

View check run for this annotation

Codecov / codecov/patch

syncer/data_fetch.go#L313 

Added line #L313 was not covered by tests
epoch,
log.Stringer("peer", peer),
)
Expand All @@ -326,6 +326,12 @@
log.Int("missing", len(missing)),
)
if len(missing) > 0 {
d.logger.WithContext(ctx).With().Info("fetching missing epoch atxs",
epoch,
log.Stringer("peer", peer),
log.Int("total", len(ed.AtxIDs)),
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

afaik, this total is not the absolute total, so we need to be careful here.

maybe @dshulyak can point to more, but I remember that I had a similar idea some time ago, and that's how I remembered.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i think this is from epoch info response, so in this case this is how many atxs are available from that peer. definitely not absolute, and not even how many are available locally

ed, err := d.fetcher.PeerEpochInfo(ctx, peer, epoch)

log.Int("missing", len(missing)),
)
if err := d.fetcher.GetAtxs(ctx, missing); err != nil {
return fmt.Errorf("get ATXs: %w", err)
}
Expand Down
22 changes: 15 additions & 7 deletions syncer/syncer.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -377,7 +377,7 @@ func (s *Syncer) synchronize(ctx context.Context) bool {
}

if err := s.syncAtx(ctx); err != nil {
s.logger.With().Error("failed to sync atxs", log.Context(ctx), log.Err(err))
s.logger.With().Info("failed to sync atxs", log.Context(ctx), log.Err(err))
return false
}

Expand Down Expand Up @@ -414,20 +414,28 @@ func (s *Syncer) synchronize(ctx context.Context) bool {

func (s *Syncer) syncAtx(ctx context.Context) error {
if !s.ListenToATXGossip() {
s.logger.WithContext(ctx).With().Info("syncing atx from genesis", s.ticker.CurrentLayer())
s.logger.WithContext(ctx).With().Info("beginning atx sync from genesis", s.ticker.CurrentLayer())
for epoch := s.lastAtxEpoch() + 1; epoch <= s.ticker.CurrentLayer().GetEpoch(); epoch++ {
s.logger.WithContext(ctx).With().Info("syncing epoch atxs",
epoch,
log.Uint32("epoch_id_current", uint32(s.ticker.CurrentLayer().GetEpoch())),
)
if err := s.fetchATXsForEpoch(ctx, epoch); err != nil {
return err
}
s.logger.WithContext(ctx).With().Info("synced atxs through epoch",
epoch,
log.Uint32("epoch_id_current", uint32(s.ticker.CurrentLayer().GetEpoch())),
)
}
s.logger.WithContext(ctx).With().Info("atxs synced to epoch", s.lastAtxEpoch())
s.logger.WithContext(ctx).With().Info("atxs sync complete", s.lastAtxEpoch())

// FIXME https://github.com/spacemeshos/go-spacemesh/issues/3987
s.logger.WithContext(ctx).With().Info("syncing malicious proofs")
s.logger.WithContext(ctx).With().Info("syncing malfeasance proofs")
if err := s.syncMalfeasance(ctx); err != nil {
return err
}
s.logger.WithContext(ctx).With().Info("malicious IDs synced")
s.logger.WithContext(ctx).With().Info("malfeasance proofs sync complete")
s.setATXSynced()
return nil
}
Expand Down Expand Up @@ -468,7 +476,7 @@ func isTooFarBehind(
outOfSyncThreshold uint32,
) bool {
if current.After(lastSynced) && current.Difference(lastSynced) >= outOfSyncThreshold {
logger.WithContext(ctx).With().Info("node is too far behind",
logger.WithContext(ctx).With().Info("node is far behind, setting out of sync",
log.Stringer("current", current),
log.Stringer("last synced", lastSynced),
log.Uint32("behind threshold", outOfSyncThreshold))
Expand Down Expand Up @@ -561,7 +569,7 @@ func (s *Syncer) syncLayer(ctx context.Context, layerID types.LayerID, peers ...
return nil
}

// fetching ATXs published the specified epoch.
// fetching published ATXs targeting the specified epoch.
func (s *Syncer) fetchATXsForEpoch(ctx context.Context, epoch types.EpochID) error {
if err := s.dataFetcher.GetEpochATXs(ctx, epoch); err != nil {
return err
Expand Down
Loading