github.com/unicornultrafoundation/go-u2u@v1.0.0-rc1.0.20240205080301-e74a83d3fadc/gossip/proclogger/llr_logger.go (about)

     1  package proclogger
     2  
     3  import (
     4  	"fmt"
     5  	"time"
     6  
     7  	"github.com/unicornultrafoundation/go-helios/hash"
     8  	"github.com/unicornultrafoundation/go-helios/native/idx"
     9  
    10  	"github.com/unicornultrafoundation/go-u2u/logger"
    11  	"github.com/unicornultrafoundation/go-u2u/native"
    12  	"github.com/unicornultrafoundation/go-u2u/native/ibr"
    13  	"github.com/unicornultrafoundation/go-u2u/native/ier"
    14  	"github.com/unicornultrafoundation/go-u2u/utils"
    15  )
    16  
    17  type dagSum struct {
    18  	connected       idx.Event
    19  	totalProcessing time.Duration
    20  }
    21  
    22  type llrSum struct {
    23  	bvs idx.Block
    24  	brs idx.Block
    25  	evs idx.Epoch
    26  	ers idx.Epoch
    27  }
    28  
    29  type Logger struct {
    30  	// summary accumulators
    31  	dagSum dagSum
    32  	llrSum llrSum
    33  
    34  	// latest logged data
    35  	lastEpoch     idx.Epoch
    36  	lastBlock     idx.Block
    37  	lastID        hash.Event
    38  	lastEventTime native.Timestamp
    39  	lastLlrTime   native.Timestamp
    40  
    41  	nextLogging time.Time
    42  
    43  	emitting  bool
    44  	noSummary bool
    45  
    46  	logger.Instance
    47  }
    48  
    49  func (l *Logger) summary(now time.Time) {
    50  	if l.noSummary {
    51  		return
    52  	}
    53  	if now.After(l.nextLogging) {
    54  		if l.llrSum != (llrSum{}) {
    55  			age := utils.PrettyDuration(now.Sub(l.lastLlrTime.Time())).String()
    56  			if l.lastLlrTime <= l.lastEventTime {
    57  				age = "none"
    58  			}
    59  			l.Log.Info("New LLR summary", "last_epoch", l.lastEpoch, "last_block", l.lastBlock,
    60  				"new_evs", l.llrSum.evs, "new_ers", l.llrSum.ers, "new_bvs", l.llrSum.bvs, "new_brs", l.llrSum.brs, "age", age)
    61  		}
    62  		if l.dagSum != (dagSum{}) {
    63  			l.Log.Info("New DAG summary", "new", l.dagSum.connected, "last_id", l.lastID.String(),
    64  				"age", utils.PrettyDuration(now.Sub(l.lastEventTime.Time())), "t", utils.PrettyDuration(l.dagSum.totalProcessing))
    65  		}
    66  		l.dagSum = dagSum{}
    67  		l.llrSum = llrSum{}
    68  		l.nextLogging = now.Add(8 * time.Second)
    69  	}
    70  }
    71  
    72  // BlockVotesConnectionStarted starts the BVs logging
    73  // Not safe for concurrent use
    74  func (l *Logger) BlockVotesConnectionStarted(bvs native.LlrSignedBlockVotes) func() {
    75  	if bvs.Val.Epoch == 0 {
    76  		return func() {}
    77  	}
    78  	l.llrSum.bvs += idx.Block(len(bvs.Val.Votes))
    79  
    80  	start := time.Now()
    81  
    82  	return func() {
    83  		if l.lastBlock < bvs.Val.LastBlock() {
    84  			l.lastBlock = bvs.Val.LastBlock()
    85  		}
    86  		now := time.Now()
    87  		// logging for the individual item
    88  		msg := "New BVs"
    89  		logType := l.Log.Debug
    90  		if l.emitting {
    91  			msg = "New BVs emitted"
    92  			logType = l.Log.Info
    93  		}
    94  		logType(msg, "id", bvs.Signed.Locator.ID(), "by", bvs.Signed.Locator.Creator,
    95  			"blocks", fmt.Sprintf("%d-%d", bvs.Val.Start, bvs.Val.LastBlock()),
    96  			"t", utils.PrettyDuration(now.Sub(start)))
    97  		l.summary(now)
    98  	}
    99  }
   100  
   101  // BlockRecordConnectionStarted starts the BR logging
   102  // Not safe for concurrent use
   103  func (l *Logger) BlockRecordConnectionStarted(br ibr.LlrIdxFullBlockRecord) func() {
   104  	l.llrSum.brs++
   105  
   106  	start := time.Now()
   107  
   108  	return func() {
   109  		if l.lastBlock < br.Idx {
   110  			l.lastBlock = br.Idx
   111  		}
   112  		if l.lastLlrTime < br.Time {
   113  			l.lastLlrTime = br.Time
   114  		}
   115  		now := time.Now()
   116  		// logging for the individual item
   117  		msg := "New BR"
   118  		logType := l.Log.Debug
   119  		logType(msg, "block", br.Idx,
   120  			"age", utils.PrettyDuration(now.Sub(br.Time.Time())),
   121  			"t", utils.PrettyDuration(now.Sub(start)))
   122  		l.summary(now)
   123  	}
   124  }
   125  
   126  // EpochVoteConnectionStarted starts the EV logging
   127  // Not safe for concurrent use
   128  func (l *Logger) EpochVoteConnectionStarted(ev native.LlrSignedEpochVote) func() {
   129  	if ev.Val.Epoch == 0 {
   130  		return func() {}
   131  	}
   132  	l.llrSum.evs++
   133  
   134  	start := time.Now()
   135  
   136  	return func() {
   137  		if l.lastEpoch < ev.Val.Epoch {
   138  			l.lastEpoch = ev.Val.Epoch
   139  		}
   140  		now := time.Now()
   141  		// logging for the individual item
   142  		msg := "New EV"
   143  		logType := l.Log.Debug
   144  		if l.emitting {
   145  			msg = "New EV emitted"
   146  			logType = l.Log.Info
   147  		}
   148  		logType(msg, "id", ev.Signed.Locator.ID(), "by", ev.Signed.Locator.Creator,
   149  			"epoch", ev.Val.Epoch,
   150  			"t", utils.PrettyDuration(now.Sub(start)))
   151  		l.summary(now)
   152  	}
   153  }
   154  
   155  // EpochRecordConnectionStarted starts the ER logging
   156  // Not safe for concurrent use
   157  func (l *Logger) EpochRecordConnectionStarted(er ier.LlrIdxFullEpochRecord) func() {
   158  	l.llrSum.ers++
   159  
   160  	start := time.Now()
   161  
   162  	return func() {
   163  		if l.lastEpoch < er.Idx {
   164  			l.lastEpoch = er.Idx
   165  		}
   166  		if l.lastLlrTime < er.EpochState.EpochStart {
   167  			l.lastLlrTime = er.EpochState.EpochStart
   168  		}
   169  		now := time.Now()
   170  		// logging for the individual item
   171  		msg := "New ER"
   172  		logType := l.Log.Debug
   173  		logType(msg, "epoch", er.Idx,
   174  			"age", utils.PrettyDuration(now.Sub(er.EpochState.EpochStart.Time())),
   175  			"t", utils.PrettyDuration(now.Sub(start)))
   176  		l.summary(now)
   177  	}
   178  }