From f47c5b371f5cf7873279624705604cf00f346e44 Mon Sep 17 00:00:00 2001 From: Felipe Gasper Date: Thu, 14 Nov 2024 21:11:15 -0500 Subject: [PATCH 1/3] Improve logging statements. --- internal/verifier/check.go | 20 +++++++++-- internal/verifier/migration_verifier.go | 47 +++++++++++++++++++++---- 2 files changed, 57 insertions(+), 10 deletions(-) diff --git a/internal/verifier/check.go b/internal/verifier/check.go index 008545bd..5a60bfb5 100644 --- a/internal/verifier/check.go +++ b/internal/verifier/check.go @@ -370,7 +370,15 @@ func FetchFailedAndIncompleteTasks(ctx context.Context, coll *mongo.Collection, func (verifier *Verifier) Work(ctx context.Context, workerNum int, wg *sync.WaitGroup) { defer wg.Done() - verifier.logger.Debug().Msgf("[Worker %d] Started", workerNum) + + verifier.logger.Debug(). + Int("workerNum", workerNum). + Msg("Worker started.") + + defer verifier.logger.Debug(). + Int("workerNum", workerNum). + Msg("Worker finished.") + for { select { case <-ctx.Done(): @@ -378,8 +386,14 @@ func (verifier *Verifier) Work(ctx context.Context, workerNum int, wg *sync.Wait default: task, err := verifier.FindNextVerifyTaskAndUpdate() if errors.Is(err, mongo.ErrNoDocuments) { - verifier.logger.Debug().Msgf("[Worker %d] No tasks found, sleeping...", workerNum) - time.Sleep(verifier.workerSleepDelayMillis * time.Millisecond) + duration := verifier.workerSleepDelayMillis * time.Millisecond + + verifier.logger.Debug(). + Int("workerNum", workerNum). + Stringer("duration", duration). + Msg("No tasks found. Sleeping.") + + time.Sleep(duration) continue } else if err != nil { panic(err) diff --git a/internal/verifier/migration_verifier.go b/internal/verifier/migration_verifier.go index 6feea6fb..84958551 100644 --- a/internal/verifier/migration_verifier.go +++ b/internal/verifier/migration_verifier.go @@ -540,7 +540,22 @@ func (verifier *Verifier) compareOneDocument(srcClientDoc, dstClientDoc bson.Raw } func (verifier *Verifier) ProcessVerifyTask(workerNum int, task *VerificationTask) { - verifier.logger.Debug().Msgf("[Worker %d] Processing verify task", workerNum) + start := time.Now() + + verifier.logger.Debug(). + Int("workerNum", workerNum). + Interface("task", task.PrimaryKey). + Msg("Processing document comparison task.") + + defer func() { + elapsed := time.Now().Sub(start) + + verifier.logger.Debug(). + Int("workerNum", workerNum). + Interface("task", task.PrimaryKey). + Stringer("timeElapsed", elapsed). + Msg("Finished document comparison task.") + }() problems, docsCount, bytesCount, err := verifier.FetchAndCompareDocuments( context.Background(), @@ -549,7 +564,11 @@ func (verifier *Verifier) ProcessVerifyTask(workerNum int, task *VerificationTas if err != nil { task.Status = verificationTaskFailed - verifier.logger.Error().Msgf("[Worker %d] Error comparing docs: %+v", workerNum, err) + verifier.logger.Error(). + Err(err). + Int("workerNum", workerNum). + Interface("task", task.PrimaryKey). + Msg("Failed to fetch and compare documents for document comparison task.") } else { task.SourceDocumentCount = docsCount task.SourceByteCount = bytesCount @@ -560,10 +579,15 @@ func (verifier *Verifier) ProcessVerifyTask(workerNum int, task *VerificationTas task.Status = verificationTaskFailed // We know we won't change lastGeneration while verification tasks are running, so no mutex needed here. if verifier.lastGeneration { - verifier.logger.Error().Msgf("[Worker %d] Verification Task %+v failed critical section and is a true error", - workerNum, task.PrimaryKey) + verifier.logger.Error(). + Int("workerNum", workerNum). + Interface("task", task.PrimaryKey). + Msg("Document comparison task failed critical section and is a true error.") } else { - verifier.logger.Debug().Msgf("[Worker %d] Verification Task %+v failed, may pass next generation", workerNum, task.PrimaryKey) + verifier.logger.Debug(). + Int("workerNum", workerNum). + Interface("task", task.PrimaryKey). + Msg("Document comparison task failed, but it may pass in the next generation.") var mismatches []VerificationResult var missingIds []interface{} @@ -594,7 +618,12 @@ func (verifier *Verifier) ProcessVerifyTask(workerNum int, task *VerificationTas // mismatched & missing docs. err := verifier.InsertFailedCompareRecheckDocs(task.QueryFilter.Namespace, idsToRecheck, dataSizes) if err != nil { - verifier.logger.Error().Msgf("[Worker %d] Error inserting document mismatch into Recheck queue: %+v", workerNum, err) + verifier.logger.Error(). + Err(err). + Int("workerNum", workerNum). + Interface("task", task.PrimaryKey). + Int("rechecksCount", len(idsToRecheck)). + Msg("Failed to enqueue rechecks after document mismatches.") } } } @@ -602,7 +631,11 @@ func (verifier *Verifier) ProcessVerifyTask(workerNum int, task *VerificationTas err = verifier.UpdateVerificationTask(task) if err != nil { - verifier.logger.Error().Msgf("Failed updating verification status: %v", err) + verifier.logger.Error(). + Err(err). + Int("workerNum", workerNum). + Interface("task", task.PrimaryKey). + Msg("Failed to update task status.") } } From 85a07242c84411d0d122ea4b13e608e78c2df0b1 Mon Sep 17 00:00:00 2001 From: Felipe Gasper Date: Thu, 14 Nov 2024 21:16:24 -0500 Subject: [PATCH 2/3] a few more --- internal/verifier/migration_verifier.go | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/internal/verifier/migration_verifier.go b/internal/verifier/migration_verifier.go index 84958551..ae19d5f1 100644 --- a/internal/verifier/migration_verifier.go +++ b/internal/verifier/migration_verifier.go @@ -459,7 +459,11 @@ func (verifier *Verifier) getDocumentsCursor(ctx context.Context, collection *mo } } findCmd := append(bson.D{{"find", collection.Name()}}, findOptions...) - verifier.logger.Debug().Msgf("getDocuments findCmd: %s opts: %v", findCmd, *runCommandOptions) + verifier.logger.Debug(). + Interface("task", task.PrimaryKey). + Str("findCmd", fmt.Sprintf("%s", findCmd)). + Str("options", fmt.Sprintf("%v", *runCommandOptions)). + Msg("getDocuments findCmd.") return collection.Database().RunCommandCursor(ctx, findCmd, runCommandOptions) } From 057fac0e8815433019a3e2e42d8a78fb775941b2 Mon Sep 17 00:00:00 2001 From: Felipe Gasper Date: Thu, 14 Nov 2024 21:18:16 -0500 Subject: [PATCH 3/3] since --- internal/verifier/migration_verifier.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/internal/verifier/migration_verifier.go b/internal/verifier/migration_verifier.go index ae19d5f1..809e4fe3 100644 --- a/internal/verifier/migration_verifier.go +++ b/internal/verifier/migration_verifier.go @@ -552,7 +552,7 @@ func (verifier *Verifier) ProcessVerifyTask(workerNum int, task *VerificationTas Msg("Processing document comparison task.") defer func() { - elapsed := time.Now().Sub(start) + elapsed := time.Since(start) verifier.logger.Debug(). Int("workerNum", workerNum).