Skip to content

Commit 8a56412

Browse files
jordanschalmjordanschalm
authored
Merge pull request #7267 from onflow/jord/v0.40-logging-level
[v0.40] Logging level adjustments
2 parents 86c40b1 + 13cd619 commit 8a56412

File tree

12 files changed

+62
-53
lines changed

12 files changed

+62
-53
lines changed

‎consensus/hotstuff/eventloop/event_loop.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -62,7 +62,7 @@ func NewEventLoop(
6262
proposals := make(chan queuedProposal, 1000)
6363

6464
el := &EventLoop{
65-
log: log,
65+
log: log.With().Str("component", "hotstuff.event_loop").Logger(),
6666
eventHandler: eventHandler,
6767
metrics: metrics,
6868
mempoolMetrics: mempoolMetrics,

‎consensus/hotstuff/timeoutaggregator/timeout_aggregator.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -137,7 +137,7 @@ func (t *TimeoutAggregator) processQueuedTimeoutObjects(ctx context.Context) err
137137
return fmt.Errorf("could not process pending TO %v: %w", timeoutObject.ID(), err)
138138
}
139139

140-
t.log.Info().
140+
t.log.Debug().
141141
Uint64("view", timeoutObject.View).
142142
Hex("signer", timeoutObject.SignerID[:]).
143143
Msg("TimeoutObject processed successfully")

‎consensus/hotstuff/voteaggregator/vote_aggregator.go

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -213,7 +213,7 @@ func (va *VoteAggregator) processQueuedVote(vote *model.Vote) error {
213213
vote.View, err)
214214
}
215215
if created {
216-
va.log.Info().Uint64("view", vote.View).Msg("vote collector is created by processing vote")
216+
va.log.Debug().Uint64("view", vote.View).Msg("vote collector is created by processing vote")
217217
}
218218

219219
err = collector.AddVote(vote)
@@ -222,7 +222,7 @@ func (va *VoteAggregator) processQueuedVote(vote *model.Vote) error {
222222
vote.View, vote.BlockID, err)
223223
}
224224

225-
va.log.Info().
225+
va.log.Debug().
226226
Uint64("view", vote.View).
227227
Hex("block_id", vote.BlockID[:]).
228228
Str("vote_id", vote.ID().String()).
@@ -251,7 +251,7 @@ func (va *VoteAggregator) processQueuedBlock(block *model.SignedProposal) error
251251
return fmt.Errorf("could not get or create collector for block %v: %w", block.Block.BlockID, err)
252252
}
253253
if created {
254-
va.log.Info().
254+
va.log.Debug().
255255
Uint64("view", block.Block.View).
256256
Hex("block_id", block.Block.BlockID[:]).
257257
Msg("vote collector is created by processing block")
@@ -268,7 +268,7 @@ func (va *VoteAggregator) processQueuedBlock(block *model.SignedProposal) error
268268
return fmt.Errorf("could not process block: %v, %w", block.Block.BlockID, err)
269269
}
270270

271-
va.log.Info().
271+
va.log.Debug().
272272
Uint64("view", block.Block.View).
273273
Hex("block_id", block.Block.BlockID[:]).
274274
Msg("block has been processed successfully")

‎engine/collection/compliance/core.go

Lines changed: 12 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -121,23 +121,25 @@ func (c *Core) OnBlockProposal(proposal flow.Slashable[*messages.ClusterBlockPro
121121

122122
log := c.log.With().
123123
Hex("origin_id", proposal.OriginID[:]).
124-
Str("chain_id", header.ChainID.String()).
125124
Uint64("block_height", header.Height).
126125
Uint64("block_view", header.View).
127126
Hex("block_id", blockID[:]).
128-
Hex("parent_id", header.ParentID[:]).
129127
Hex("ref_block_id", block.Message.Payload.ReferenceBlockID[:]).
130128
Hex("collection_id", logging.Entity(block.Message.Payload.Collection)).
131129
Int("tx_count", block.Message.Payload.Collection.Len()).
132-
Time("timestamp", header.Timestamp).
130+
Hex("parent_id", header.ParentID[:]).
133131
Hex("proposer", header.ProposerID[:]).
134-
Hex("parent_signer_indices", header.ParentVoterIndices).
135-
Uint64("finalized_height", finalHeight).
136-
Uint64("finalized_view", finalView).
132+
Time("timestamp", header.Timestamp).
137133
Logger()
138134
if log.Debug().Enabled() {
139-
log = log.With().Strs("tx_ids",
140-
flow.IdentifierList(block.Message.Payload.Collection.Light().Transactions).Strings()).Logger()
135+
log = log.With().
136+
Uint64("finalized_height", finalHeight).
137+
Uint64("finalized_view", finalView).
138+
Str("chain_id", header.ChainID.String()).
139+
Hex("payload_hash", header.PayloadHash[:]).
140+
Hex("parent_signer_indices", header.ParentVoterIndices).
141+
Strs("tx_ids", flow.IdentifierList(block.Message.Payload.Collection.Light().Transactions).Strings()).
142+
Logger()
141143
}
142144
log.Info().Msg("block proposal received")
143145

@@ -315,7 +317,7 @@ func (c *Core) processBlockProposal(proposal *cluster.Block) error {
315317
Hex("proposer", header.ProposerID[:]).
316318
Hex("parent_signer_indices", header.ParentVoterIndices).
317319
Logger()
318-
log.Info().Msg("processing block proposal")
320+
log.Debug().Msg("processing block proposal")
319321

320322
hotstuffProposal := model.SignedProposalFromFlow(header)
321323
err := c.validator.ValidateProposal(hotstuffProposal)
@@ -355,7 +357,7 @@ func (c *Core) processBlockProposal(proposal *cluster.Block) error {
355357

356358
// submit the model to hotstuff for processing
357359
// TODO replace with pubsub https://github.com/dapperlabs/flow-go/issues/6395
358-
log.Info().Msg("forwarding block proposal to hotstuff")
360+
log.Debug().Msg("forwarding block proposal to hotstuff")
359361
c.hotstuff.SubmitProposal(hotstuffProposal)
360362

361363
return nil

‎engine/collection/message_hub/message_hub.go

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -247,7 +247,7 @@ func (h *MessageHub) sendOwnMessages(ctx context.Context) error {
247247
// No errors are expected during normal operations.
248248
func (h *MessageHub) sendOwnTimeout(timeout *model.TimeoutObject) error {
249249
log := timeout.LogContext(h.log).Logger()
250-
log.Info().Msg("processing timeout broadcast request from hotstuff")
250+
log.Debug().Msg("processing timeout broadcast request from hotstuff")
251251

252252
// Retrieve all collection nodes in our cluster (excluding myself).
253253
recipients, err := h.state.Final().Identities(h.clusterIdentityFilter)
@@ -270,7 +270,7 @@ func (h *MessageHub) sendOwnTimeout(timeout *model.TimeoutObject) error {
270270
}
271271
return nil
272272
}
273-
log.Info().Msg("cluster timeout was broadcast")
273+
log.Debug().Msg("cluster timeout was broadcast")
274274
h.engineMetrics.MessageSent(metrics.EngineCollectionMessageHub, metrics.MessageTimeoutObject)
275275

276276
return nil
@@ -284,15 +284,15 @@ func (h *MessageHub) sendOwnVote(packed *packedVote) error {
284284
Uint64("collection_view", packed.vote.View).
285285
Hex("recipient_id", packed.recipientID[:]).
286286
Logger()
287-
log.Info().Msg("processing vote transmission request from hotstuff")
287+
log.Debug().Msg("processing vote transmission request from hotstuff")
288288

289289
// send the vote the desired recipient
290290
err := h.con.Unicast(packed.vote, packed.recipientID)
291291
if err != nil {
292292
log.Err(err).Msg("could not send vote")
293293
return nil
294294
}
295-
log.Info().Msg("collection vote transmitted")
295+
log.Debug().Msg("collection vote transmitted")
296296
h.engineMetrics.MessageSent(metrics.EngineCollectionMessageHub, metrics.MessageBlockVote)
297297

298298
return nil
@@ -460,7 +460,7 @@ func (h *MessageHub) forwardToOwnVoteAggregator(vote *messages.ClusterBlockVote,
460460
SignerID: originID,
461461
SigData: vote.SigData,
462462
}
463-
h.log.Info().
463+
h.log.Debug().
464464
Uint64("block_view", v.View).
465465
Hex("block_id", v.BlockID[:]).
466466
Hex("voter", v.SignerID[:]).
@@ -473,7 +473,7 @@ func (h *MessageHub) forwardToOwnVoteAggregator(vote *messages.ClusterBlockVote,
473473
// Per API convention, timeoutAggregator` is non-blocking, hence, this call returns quickly.
474474
func (h *MessageHub) forwardToOwnTimeoutAggregator(t *model.TimeoutObject) {
475475
h.engineMetrics.MessageReceived(metrics.EngineCollectionMessageHub, metrics.MessageTimeoutObject)
476-
h.log.Info().
476+
h.log.Debug().
477477
Hex("origin_id", t.SignerID[:]).
478478
Uint64("view", t.View).
479479
Str("timeout_id", t.ID().String()).

‎engine/common/follower/compliance_core.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -123,7 +123,7 @@ func (c *ComplianceCore) OnBlockRange(originID flow.Identifier, batch []*flow.Bl
123123
Int("range_length", len(batch)).
124124
Logger()
125125

126-
log.Info().Msg("processing block range")
126+
log.Debug().Msg("processing block range")
127127

128128
if c.pendingCache.Peek(hotstuffProposal.Block.BlockID) == nil {
129129
log.Debug().Msg("block not found in cache, performing validation")

‎engine/consensus/compliance/core.go

Lines changed: 14 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -23,7 +23,6 @@ import (
2323
"github.com/onflow/flow-go/state"
2424
"github.com/onflow/flow-go/state/protocol"
2525
"github.com/onflow/flow-go/storage"
26-
"github.com/onflow/flow-go/utils/logging"
2726
)
2827

2928
// Core contains the central business logic for the main consensus' compliance engine.
@@ -133,19 +132,23 @@ func (c *Core) OnBlockProposal(proposal flow.Slashable[*messages.BlockProposal])
133132

134133
log := c.log.With().
135134
Hex("origin_id", proposal.OriginID[:]).
136-
Str("chain_id", header.ChainID.String()).
137135
Uint64("block_height", header.Height).
138136
Uint64("block_view", header.View).
139-
Hex("block_id", logging.Entity(header)).
137+
Hex("block_id", blockID[:]).
140138
Hex("parent_id", header.ParentID[:]).
141-
Hex("payload_hash", header.PayloadHash[:]).
142-
Time("timestamp", header.Timestamp).
143139
Hex("proposer", header.ProposerID[:]).
144-
Hex("parent_signer_indices", header.ParentVoterIndices).
145-
Str("traceID", traceID). // traceID is used to connect logs to traces
146-
Uint64("finalized_height", finalHeight).
147-
Uint64("finalized_view", finalView).
140+
Time("timestamp", header.Timestamp).
148141
Logger()
142+
if log.Debug().Enabled() {
143+
log = log.With().
144+
Uint64("finalized_height", finalHeight).
145+
Uint64("finalized_view", finalView).
146+
Str("chain_id", header.ChainID.String()).
147+
Hex("payload_hash", header.PayloadHash[:]).
148+
Hex("parent_signer_indices", header.ParentVoterIndices).
149+
Str("traceID", traceID). // traceID is used to connect logs to traces
150+
Logger()
151+
}
149152
log.Info().Msg("block proposal received")
150153

151154
// drop proposals below the finalized threshold
@@ -360,7 +363,7 @@ func (c *Core) processBlockProposal(proposal *flow.Block) error {
360363
Hex("proposer", header.ProposerID[:]).
361364
Hex("parent_signer_indices", header.ParentVoterIndices).
362365
Logger()
363-
log.Info().Msg("processing block proposal")
366+
log.Debug().Msg("processing block proposal")
364367

365368
// see if the block is a valid extension of the protocol state
366369
block := &flow.Block{
@@ -387,7 +390,7 @@ func (c *Core) processBlockProposal(proposal *flow.Block) error {
387390

388391
// submit the model to hotstuff for processing
389392
// TODO replace with pubsub https://github.com/dapperlabs/flow-go/issues/6395
390-
log.Info().Msg("forwarding block proposal to hotstuff")
393+
log.Debug().Msg("forwarding block proposal to hotstuff")
391394
c.hotstuff.SubmitProposal(hotstuffProposal)
392395

393396
return nil

‎engine/consensus/matching/core.go

Lines changed: 10 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -199,7 +199,7 @@ func (c *Core) processReceipt(receipt *flow.ExecutionReceipt) (bool, error) {
199199
Uint64("block_view", executedBlock.View).
200200
Uint64("block_height", executedBlock.Height).
201201
Logger()
202-
log.Info().Msg("execution receipt received")
202+
log.Debug().Msg("execution receipt received")
203203

204204
// if Execution Receipt is for block whose height is lower or equal to already sealed height
205205
// => drop Receipt
@@ -245,7 +245,7 @@ func (c *Core) processReceipt(receipt *flow.ExecutionReceipt) (bool, error) {
245245
return false, fmt.Errorf("failed to store receipt: %w", err)
246246
}
247247
if added {
248-
log.Info().Msg("execution result processed and stored")
248+
log.Debug().Msg("execution result processed and stored")
249249
}
250250

251251
return added, nil
@@ -382,13 +382,19 @@ func (c *Core) OnBlockFinalization() error {
382382
lastSealed.ID(), lastSealed.Height, err)
383383
}
384384

385-
c.log.Info().
385+
log := c.log.With().
386386
Uint64("first_height_missing_result", firstMissingHeight).
387387
Uint("seals_size", c.seals.Size()).
388388
Uint("receipts_size", c.receipts.Size()).
389389
Int("pending_receipt_requests", pendingReceiptRequests).
390390
Int64("duration_ms", time.Since(startTime).Milliseconds()).
391-
Msg("finalized block processed successfully")
391+
Logger()
392+
// this runs frequently, so we only log at info-level if there are pending requests
393+
if pendingReceiptRequests > 0 {
394+
log.Info().Msg("finalized block processed successfully")
395+
} else {
396+
log.Debug().Msg("finalized block processed successfully")
397+
}
392398

393399
return nil
394400
}

‎engine/consensus/message_hub/message_hub.go

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -230,7 +230,7 @@ func (h *MessageHub) sendOwnMessages(ctx context.Context) error {
230230
// No errors are expected during normal operations.
231231
func (h *MessageHub) sendOwnTimeout(timeout *model.TimeoutObject) error {
232232
log := timeout.LogContext(h.log).Logger()
233-
log.Info().Msg("processing timeout broadcast request from hotstuff")
233+
log.Debug().Msg("processing timeout broadcast request from hotstuff")
234234

235235
// Retrieve all consensus nodes (excluding myself).
236236
// CAUTION: We must include consensus nodes that are joining, because otherwise
@@ -260,7 +260,7 @@ func (h *MessageHub) sendOwnTimeout(timeout *model.TimeoutObject) error {
260260
}
261261
return nil
262262
}
263-
log.Info().Msg("consensus timeout was broadcast")
263+
log.Debug().Msg("consensus timeout was broadcast")
264264
h.engineMetrics.MessageSent(metrics.EngineConsensusMessageHub, metrics.MessageTimeoutObject)
265265

266266
return nil
@@ -274,7 +274,7 @@ func (h *MessageHub) sendOwnVote(packed *packedVote) error {
274274
Uint64("block_view", packed.vote.View).
275275
Hex("recipient_id", packed.recipientID[:]).
276276
Logger()
277-
log.Info().Msg("processing vote transmission request from hotstuff")
277+
log.Debug().Msg("processing vote transmission request from hotstuff")
278278

279279
// send the vote the desired recipient
280280
err := h.con.Unicast(packed.vote, packed.recipientID)
@@ -283,7 +283,7 @@ func (h *MessageHub) sendOwnVote(packed *packedVote) error {
283283
return nil
284284
}
285285
h.engineMetrics.MessageSent(metrics.EngineConsensusMessageHub, metrics.MessageBlockVote)
286-
log.Info().Msg("block vote transmitted")
286+
log.Debug().Msg("block vote transmitted")
287287

288288
return nil
289289
}
@@ -374,7 +374,7 @@ func (h *MessageHub) provideProposal(proposal *messages.BlockProposal, recipient
374374
Hex("block_id", blockID[:]).
375375
Hex("parent_id", header.ParentID[:]).
376376
Logger()
377-
log.Info().Msg("block proposal submitted for propagation")
377+
log.Debug().Msg("block proposal submitted for propagation")
378378

379379
// submit the block to the targets
380380
err := h.pushBlocksCon.Publish(proposal, recipients.NodeIDs()...)
@@ -495,7 +495,7 @@ func (h *MessageHub) forwardToOwnVoteAggregator(vote *messages.BlockVote, origin
495495
SignerID: originID,
496496
SigData: vote.SigData,
497497
}
498-
h.log.Info().
498+
h.log.Debug().
499499
Uint64("block_view", v.View).
500500
Hex("block_id", v.BlockID[:]).
501501
Hex("voter", v.SignerID[:]).
@@ -508,7 +508,7 @@ func (h *MessageHub) forwardToOwnVoteAggregator(vote *messages.BlockVote, origin
508508
// Per API convention, timeoutAggregator` is non-blocking, hence, this call returns quickly.
509509
func (h *MessageHub) forwardToOwnTimeoutAggregator(t *model.TimeoutObject) {
510510
h.engineMetrics.MessageReceived(metrics.EngineConsensusMessageHub, metrics.MessageTimeoutObject)
511-
h.log.Info().
511+
h.log.Debug().
512512
Hex("origin_id", t.SignerID[:]).
513513
Uint64("view", t.View).
514514
Str("timeout_id", t.ID().String()).

‎engine/verification/assigner/engine.go

Lines changed: 4 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,6 @@ import (
66
"sync/atomic"
77

88
"github.com/rs/zerolog"
9-
"github.com/rs/zerolog/log"
109

1110
"github.com/onflow/flow-go/model/chunks"
1211
"github.com/onflow/flow-go/model/flow"
@@ -77,7 +76,7 @@ func (e *Engine) resultChunkAssignment(ctx context.Context,
7776
incorporatingBlock flow.Identifier,
7877
) (flow.ChunkList, error) {
7978
resultID := result.ID()
80-
log := log.With().
79+
log := e.log.With().
8180
Hex("result_id", logging.ID(resultID)).
8281
Hex("executed_block_id", logging.ID(result.BlockID)).
8382
Hex("incorporating_block_id", logging.ID(incorporatingBlock)).
@@ -101,8 +100,7 @@ func (e *Engine) resultChunkAssignment(ctx context.Context,
101100
}
102101
e.metrics.OnChunksAssignmentDoneAtAssigner(len(chunkList))
103102

104-
// TODO: de-escalate to debug level on stable version.
105-
log.Info().
103+
log.Debug().
106104
Int("total_chunks", len(result.Chunks)).
107105
Int("total_assigned_chunks", len(chunkList)).
108106
Msg("chunk assignment done")
@@ -144,7 +142,7 @@ func (e *Engine) processChunk(chunk *flow.Chunk, resultID flow.Identifier, block
144142

145143
// notifies chunk queue consumer of a new chunk
146144
e.newChunkListener.Check()
147-
lg.Info().Msg("chunk locator successfully pushed to chunks queue")
145+
lg.Debug().Msg("chunk locator successfully pushed to chunks queue")
148146

149147
return true, nil
150148
}
@@ -229,7 +227,7 @@ func (e *Engine) processFinalizedBlock(ctx context.Context, block *flow.Block) {
229227
}
230228

231229
e.metrics.OnFinalizedBlockArrivedAtAssigner(block.Header.Height)
232-
lg.Info().
230+
lg.Debug().
233231
Uint64("total_assigned_chunks", assignedChunksCount).
234232
Uint64("total_processed_chunks", processedChunksCount).
235233
Msg("finished processing finalized block")

‎module/jobqueue/consumer.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -189,7 +189,7 @@ func (c *Consumer) checkProcessable() {
189189
}
190190

191191
if processingCount > 0 {
192-
c.log.Info().Int64("processing", processingCount).Msg("processing jobs")
192+
c.log.Debug().Int64("processing", processingCount).Msg("processing jobs")
193193
} else {
194194
c.log.Debug().Bool("running", c.running).Msg("no job found")
195195
}

‎network/underlay/network.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -921,7 +921,7 @@ func (n *Network) handleIncomingStream(s libp2pnet.Stream) {
921921
// qualify the logger with local and remote address
922922
log := p2putils.StreamLogger(n.logger, s)
923923

924-
log.Info().Msg("incoming stream received")
924+
log.Debug().Msg("incoming stream received")
925925

926926
success := false
927927

0 commit comments

Comments
 (0)