Enhanced EventWatcher logs (#5558)

* Show push error log earlier than reporting Signed-off-by: t-kikuc <tkikuchi07f@gmail.com> * Use WarnLog in retry Signed-off-by: t-kikuc <tkikuchi07f@gmail.com> * clarify log messages Signed-off-by: t-kikuc <tkikuchi07f@gmail.com> * clarify log messages Signed-off-by: t-kikuc <tkikuchi07f@gmail.com> * add TestDoCalls for asserting counts Signed-off-by: t-kikuc <tkikuchi07f@gmail.com> * add eventIDs in log Signed-off-by: t-kikuc <tkikuchi07f@gmail.com> * enrich logs in updateValues Signed-off-by: t-kikuc <tkikuchi07f@gmail.com> * nits Signed-off-by: t-kikuc <tkikuchi07f@gmail.com> * Revert "add TestDoCalls for asserting counts" This reverts commit de3f112. Signed-off-by: t-kikuc <tkikuchi07f@gmail.com> --------- Signed-off-by: t-kikuc <tkikuchi07f@gmail.com>
pipe-cd · Feb 7, 2025 · 75db0fa · 75db0fa
1 parent f52a27b
commit 75db0fa
Showing 1 changed file with 35 additions and 10 deletions.
diff --git a/pkg/app/piped/eventwatcher/eventwatcher.go b/pkg/app/piped/eventwatcher/eventwatcher.go
@@ -183,7 +183,7 @@ func (w *watcher) run(ctx context.Context, repo git.Repo, repoCfg config.PipedRe
 		case <-ticker.C:
 			err := repo.Pull(ctx, repo.GetClonedBranch())
 			if err != nil {
-				w.logger.Error("failed to perform git pull",
+				w.logger.Error("failed to perform git pull. will retry in the next loop",
 					zap.String("repo-id", repoCfg.RepoID),
 					zap.String("branch", repo.GetClonedBranch()),
 					zap.Error(err),
@@ -233,6 +233,7 @@ func (w *watcher) run(ctx context.Context, repo git.Repo, repoCfg config.PipedRe
 				if err := w.updateValues(ctx, repo, repoCfg.RepoID, cfg.Events, commitMsg); err != nil {
 					w.logger.Error("failed to update the values",
 						zap.String("repo-id", repoCfg.RepoID),
+						zap.String("branch", repo.GetClonedBranch()),
 						zap.Error(err),
 					)
 				}
@@ -294,6 +295,7 @@ func (w *watcher) run(ctx context.Context, repo git.Repo, repoCfg config.PipedRe
 			if err := w.execute(ctx, repo, repoCfg.RepoID, cfgs); err != nil {
 				w.logger.Error("failed to execute the event from application configuration",
 					zap.String("repo-id", repoCfg.RepoID),
+					zap.String("branch", repo.GetClonedBranch()),
 					zap.Error(err),
 				)
 			}
@@ -456,28 +458,40 @@ func (w *watcher) execute(ctx context.Context, repo git.Repo, repoID string, eve
 	var responseError error
 	retry := backoff.NewRetry(retryPushNum, backoff.NewConstant(retryPushInterval))
 	for branch, events := range branchHandledEvents {
+		eventIDs := make([]string, 0, len(events))
+		for _, e := range events {
+			eventIDs = append(eventIDs, e.Id)
+		}
+		zlogger := w.logger.With(
+			zap.String("repo-id", repoID),
+			zap.String("branch", tmpRepo.GetClonedBranch()),
+			zap.Strings("event-ids", eventIDs),
+		)
+
 		_, err = retry.Do(ctx, func() (interface{}, error) {
 			if err := tmpRepo.Push(ctx, branch); err != nil {
-				w.logger.Error("failed to push commits", zap.String("repo-id", repoID), zap.String("branch", branch), zap.Error(err))
+				zlogger.Warn(fmt.Sprintf("failed to push commits. retry attempt %d/%d", retry.Calls(), retryPushNum), zap.Error(err))
 				return nil, err
 			}
 			return nil, nil
 		})
 
 		if err == nil {
 			if _, err := w.apiClient.ReportEventStatuses(ctx, &pipedservice.ReportEventStatusesRequest{Events: events}); err != nil {
-				w.logger.Error("failed to report event statuses", zap.Error(err))
+				zlogger.Error("failed to report event statuses", zap.Error(err))
 			}
 			w.executionMilestoneMap.Store(repoID, maxTimestamp)
 			continue
 		}
 
 		// If push fails because the local branch was not fresh, exit to retry again in the next interval.
 		if err == git.ErrBranchNotFresh {
-			w.logger.Warn("failed to push commits", zap.Error(err))
+			zlogger.Warn("failed to push commits. local branch was not up-to-date. will retry in the next loop", zap.Error(err))
 			continue
 		}
 
+		zlogger.Error("failed to push commits", zap.Error(err))
+
 		// If push fails because of the other reason, re-set all statuses to FAILURE.
 		for i := range events {
 			if events[i].Status == model.EventStatus_EVENT_FAILURE {
@@ -487,7 +501,7 @@ func (w *watcher) execute(ctx context.Context, repo git.Repo, repoID string, eve
 			events[i].StatusDescription = fmt.Sprintf("Failed to push changed files: %v", err)
 		}
 		if _, err := w.apiClient.ReportEventStatuses(ctx, &pipedservice.ReportEventStatusesRequest{Events: events}); err != nil {
-			w.logger.Error("failed to report event statuses", zap.Error(err))
+			zlogger.Error("failed to report event statuses", zap.Error(err))
 		}
 		w.executionMilestoneMap.Store(repoID, maxTimestamp)
 		responseError = errors.Join(responseError, err)
@@ -600,17 +614,27 @@ func (w *watcher) updateValues(ctx context.Context, repo git.Repo, repoID string
 		return nil
 	}
 
+	eventIDs := make([]string, 0, len(handledEvents))
+	for _, e := range handledEvents {
+		eventIDs = append(eventIDs, e.Id)
+	}
+	zlogger := w.logger.With(
+		zap.String("repo-id", repoID),
+		zap.String("branch", tmpRepo.GetClonedBranch()),
+		zap.Strings("event-ids", eventIDs),
+	)
+
 	retry := backoff.NewRetry(retryPushNum, backoff.NewConstant(retryPushInterval))
 	_, err = retry.Do(ctx, func() (interface{}, error) {
 		if err := tmpRepo.Push(ctx, tmpRepo.GetClonedBranch()); err != nil {
-			w.logger.Error("failed to push commits", zap.String("repo-id", repoID), zap.String("branch", tmpRepo.GetClonedBranch()), zap.Error(err))
+			zlogger.Warn(fmt.Sprintf("failed to push commits. retry attempt %d/%d", retry.Calls(), retryPushNum), zap.Error(err))
 			return nil, err
 		}
 		return nil, nil
 	})
 	if err == nil {
 		if _, err := w.apiClient.ReportEventStatuses(ctx, &pipedservice.ReportEventStatusesRequest{Events: handledEvents}); err != nil {
-			w.logger.Error("failed to report event statuses", zap.Error(err))
+			zlogger.Error("failed to report event statuses", zap.Error(err))
 			return err
 		}
 		w.milestoneMap.Store(repoID, maxTimestamp)
@@ -619,10 +643,12 @@ func (w *watcher) updateValues(ctx context.Context, repo git.Repo, repoID string
 
 	// If push fails because the local branch was not fresh, exit to retry again in the next interval.
 	if err == git.ErrBranchNotFresh {
-		w.logger.Warn("failed to push commits", zap.Error(err))
+		zlogger.Warn("failed to push commits. local branch was not up-to-date. will retry in the next loop", zap.Error(err))
 		return nil
 	}
 
+	zlogger.Error("failed to push commits", zap.Error(err))
+
 	// If push fails because of the other reason, re-set all statuses to FAILURE.
 	for i := range handledEvents {
 		if handledEvents[i].Status == model.EventStatus_EVENT_FAILURE {
@@ -632,11 +658,10 @@ func (w *watcher) updateValues(ctx context.Context, repo git.Repo, repoID string
 		handledEvents[i].StatusDescription = fmt.Sprintf("Failed to push changed files: %v", err)
 	}
 	if _, err := w.apiClient.ReportEventStatuses(ctx, &pipedservice.ReportEventStatusesRequest{Events: handledEvents}); err != nil {
-		w.logger.Error("failed to report event statuses: %w", zap.Error(err))
+		zlogger.Error("failed to report event statuses: %w", zap.Error(err))
 		return err
 	}
 	w.milestoneMap.Store(repoID, maxTimestamp)
-	w.logger.Error("failed to push commits", zap.Error(err))
 	return err
 }