From f52e36fe01f133aeda352647c8924253b7ab69e6 Mon Sep 17 00:00:00 2001
From: pk910 <philipp@pk910.de>
Date: Tue, 19 Dec 2023 10:54:55 +0100
Subject: [PATCH] improve long running task logging

---
 .../tasks/check_consensus_attestation_stats/task.go      | 5 ++++-
 pkg/coordinator/tasks/check_consensus_finality/task.go   | 6 +++---
 pkg/coordinator/tasks/check_consensus_reorgs/task.go     | 9 +++++++--
 3 files changed, 14 insertions(+), 6 deletions(-)

diff --git a/pkg/coordinator/tasks/check_consensus_attestation_stats/task.go b/pkg/coordinator/tasks/check_consensus_attestation_stats/task.go
index 27abb85..c6d271e 100644
--- a/pkg/coordinator/tasks/check_consensus_attestation_stats/task.go
+++ b/pkg/coordinator/tasks/check_consensus_attestation_stats/task.go
@@ -117,6 +117,8 @@ func (t *Task) Execute(ctx context.Context) error {
 	// start vote counting from next epoch as current epoch might be incomplete
 	lastCheckedEpoch := currentEpoch.Number()
 
+	t.logger.Infof("current epoch: %v, starting attestation aggregation at epoch %v", lastCheckedEpoch, lastCheckedEpoch+1)
+
 	t.attesterDutyMap = map[uint64]map[phase0.Root]*attesterDuties{}
 	defer func() {
 		t.attesterDutyMap = nil
@@ -139,7 +141,6 @@ func (t *Task) Execute(ctx context.Context) error {
 				break
 			}
 
-			t.logger.Infof("check epoch %v votes", checkEpoch)
 			t.runAttestationStatsCheck(ctx, checkEpoch)
 
 			lastCheckedEpoch = checkEpoch
@@ -253,6 +254,8 @@ func (t *Task) runAttestationStatsCheck(ctx context.Context, epoch uint64) {
 			}
 		}
 
+		t.logger.Infof("epoch %v attestation check result: %v. passed checks: %v, want: %v", epoch, result, t.passedEpochs, t.config.MinCheckedEpochs)
+
 		break
 	}
 }
diff --git a/pkg/coordinator/tasks/check_consensus_finality/task.go b/pkg/coordinator/tasks/check_consensus_finality/task.go
index 6e90b95..8522a43 100644
--- a/pkg/coordinator/tasks/check_consensus_finality/task.go
+++ b/pkg/coordinator/tasks/check_consensus_finality/task.go
@@ -131,17 +131,17 @@ func (t *Task) runFinalityCheck() bool {
 	unfinalizedEpochs := currentEpoch.Number() - uint64(finalizedEpoch)
 
 	if t.config.MinUnfinalizedEpochs > 0 && unfinalizedEpochs < t.config.MinUnfinalizedEpochs {
-		t.logger.Debugf("check failed: minUnfinalizedEpochs (have: %v, want >= %v)", unfinalizedEpochs, t.config.MinUnfinalizedEpochs)
+		t.logger.Infof("check failed: minUnfinalizedEpochs (have: %v, want >= %v)", unfinalizedEpochs, t.config.MinUnfinalizedEpochs)
 		return false
 	}
 
 	if t.config.MaxUnfinalizedEpochs > 0 && unfinalizedEpochs > t.config.MaxUnfinalizedEpochs {
-		t.logger.Debugf("check failed: maxUnfinalizedEpochs (have: %v, want <= %v)", unfinalizedEpochs, t.config.MaxUnfinalizedEpochs)
+		t.logger.Infof("check failed: maxUnfinalizedEpochs (have: %v, want <= %v)", unfinalizedEpochs, t.config.MaxUnfinalizedEpochs)
 		return false
 	}
 
 	if t.config.MinFinalizedEpochs > 0 && uint64(finalizedEpoch) < t.config.MinFinalizedEpochs {
-		t.logger.Debugf("check failed: minFinalizedEpochs (have: %v, want >= %v)", finalizedEpoch, t.config.MinFinalizedEpochs)
+		t.logger.Infof("check failed: minFinalizedEpochs (have: %v, want >= %v)", finalizedEpoch, t.config.MinFinalizedEpochs)
 		return false
 	}
 
diff --git a/pkg/coordinator/tasks/check_consensus_reorgs/task.go b/pkg/coordinator/tasks/check_consensus_reorgs/task.go
index 0074932..b585b28 100644
--- a/pkg/coordinator/tasks/check_consensus_reorgs/task.go
+++ b/pkg/coordinator/tasks/check_consensus_reorgs/task.go
@@ -118,12 +118,14 @@ func (t *Task) Execute(ctx context.Context) error {
 
 				if t.config.MaxReorgDistance > 0 && t.maxReorgDistance > t.config.MaxReorgDistance {
 					t.ctx.SetResult(types.TaskResultFailure)
+					t.logger.Infof("task failed: max reorg distance (%v) exceeded, reorg distance around slot %v: %v", t.config.MaxReorgDistance, block.Slot, t.maxReorgDistance)
+
 					return fmt.Errorf("max reorg distance (%v) exceeded:  %v -> %v (%v)", t.config.MaxReorgDistance, lastBlock.Root.String(), block.Root.String(), t.maxReorgDistance)
 				}
-
-				t.ctx.SetResult(t.runCheck())
 			}
 
+			t.ctx.SetResult(t.runCheck())
+
 			lastBlock = block
 		case <-ctx.Done():
 			return ctx.Err()
@@ -136,16 +138,19 @@ func (t *Task) runCheck() types.TaskResult {
 
 	_, currentEpoch, err := consensusPool.GetBlockCache().GetWallclock().Now()
 	if err != nil {
+		t.logger.Warnf("check missed: could not get current epoch from wall clock")
 		return types.TaskResultNone
 	}
 
 	epochCount := currentEpoch.Number() - t.startEpoch
 
 	if t.config.MinCheckEpochCount > 0 && epochCount < t.config.MinCheckEpochCount {
+		t.logger.Warnf("Check missed: checked %v epochs, but need >= %v", epochCount, t.config.MinCheckEpochCount)
 		return types.TaskResultNone
 	}
 
 	if t.config.MaxReorgsPerEpoch > 0 && epochCount > 0 && float64(t.totalReorgs)/float64(epochCount) > t.config.MaxReorgsPerEpoch {
+		t.logger.Warnf("check failed: max reorgs per epoch exceeded. (have: %v, want <= %v)", float64(t.totalReorgs)/float64(epochCount), t.config.MaxReorgsPerEpoch)
 		return types.TaskResultFailure
 	}