chore: add race-trace logs for PR comments

sometimes two controller workers can post the same PR comment at nearly
the same time. This adds breadcrumbs so we can see who did what and
when, and quickly debug duplicate-comment races.

Adds a per-call dedup_trace ID and debug-phase logs across initial list,
jitter wait, post-jitter list, create start/done, post-create list,
primary selection, delete attempts/completions, and dedup completion.

Improves marker observability by logging fetched vs matched counts,
compact matched comment id/timestamp data, marker hash/length (no full
marker body), plus controller_label with explicit unknown fallback.

Adds validation-path correlation debug logging before CreateComment in
reportValidationErrors with validation count and event/repo/branch
context.

Enhances TestGithubSecondFlakyPullRequestBadYaml diagnostics:
per-comment compact metadata, bounded recheck loop with attempt logs,
and actionable final assertion details.

Adds unit coverage in TestCreateCommentDedupLogging to verify phase logs
and correlation fields for no/one/multiple existing marker scenarios.

Signed-off-by: Chmouel Boudjnah <chmouel@redhat.com>

Author: chmouel

pkg/pipelineascode/errors.go

@@ -63,6 +63,28 @@ func (p *PacRun) reportValidationErrors(ctx context.Context, repo *v1alpha1.Repo
 	}
 	markdownErrMessage := fmt.Sprintf(`%s
 %s`, provider.ValidationErrorTemplate, strings.Join(errorRows, "\n"))
+
+	eventID := "unknown"
+	org := "unknown"
+	repository := "unknown"
+	sourceBranch := "unknown"
+	targetBranch := "unknown"
+	pr := 0
+	if p.event != nil {
+		org = p.event.Organization
+		repository = p.event.Repository
+		sourceBranch = p.event.HeadBranch
+		targetBranch = p.event.BaseBranch
+		pr = p.event.PullRequestNumber
+		if p.event.Request != nil {
+			if id := p.event.Request.Header.Get("X-GitHub-Delivery"); id != "" {
+				eventID = id
+			}
+		}
+	}
+	p.debugf("reportValidationErrors: create_comment validation_error_count=%d event_id=%s pr=%d repo=%s/%s namespace=%s source_branch=%s target_branch=%s",
+		len(errorRows), eventID, pr, org, repository, repo.GetNamespace(), sourceBranch, targetBranch)
+
 	if err := p.vcx.CreateComment(ctx, p.event, markdownErrMessage, provider.ValidationErrorTemplate); err != nil {
 		p.eventEmitter.EmitMessage(repo, zap.ErrorLevel, "PipelineRunCommentCreationError",
 			fmt.Sprintf("failed to create comment: %s", err.Error()))

pkg/provider/github/github.go

@@ -2,7 +2,9 @@ package github
 
 import (
 	"context"
+	"crypto/sha256"
 	"encoding/base64"
+	"encoding/hex"
 	"fmt"
 	"math/rand"
 	"net/http"
@@ -750,7 +752,117 @@ func (v *Provider) GetTemplate(commentType provider.CommentType) string {
 	return provider.GetHTMLTemplate(commentType)
 }
 
-func (v *Provider) listCommentsByMarker(ctx context.Context, event *info.Event, marker string) ([]*github.IssueComment, error) {
+type commentTraceLogContext struct {
+	dedupTrace      string
+	eventID         string
+	markerHash      string
+	markerLen       int
+	controllerLabel string
+}
+
+func newDedupTraceID() string {
+	//nolint:gosec // best-effort correlation ID for debug logs only
+	return fmt.Sprintf("%x-%04x", time.Now().UnixNano(), rand.Intn(1<<16))
+}
+
+func markerHash(marker string) string {
+	if marker == "" {
+		return "none"
+	}
+	sum := sha256.Sum256([]byte(marker))
+	digest := hex.EncodeToString(sum[:])
+	if len(digest) > 12 {
+		return digest[:12]
+	}
+	return digest
+}
+
+func formatCommentTime(ts github.Timestamp) string {
+	if ts.IsZero() {
+		return "unknown"
+	}
+	return ts.UTC().Format(time.RFC3339)
+}
+
+func compactCommentIDs(comments []*github.IssueComment) []string {
+	out := make([]string, 0, len(comments))
+	for _, comment := range comments {
+		out = append(out, fmt.Sprintf("%d@%s", comment.GetID(), formatCommentTime(comment.GetCreatedAt())))
+	}
+	return out
+}
+
+func responseStatusCode(resp *github.Response) int {
+	if resp == nil {
+		return 0
+	}
+	return resp.StatusCode
+}
+
+func eventID(event *info.Event) string {
+	if event == nil || event.Request == nil {
+		return "unknown"
+	}
+	if id := event.Request.Header.Get("X-GitHub-Delivery"); id != "" {
+		return id
+	}
+	return "unknown"
+}
+
+func (v *Provider) controllerLabel(ctx context.Context) string {
+	if name := info.GetCurrentControllerName(ctx); name != "" {
+		return name
+	}
+	if v.Run != nil && v.Run.Info.Controller != nil && v.Run.Info.Controller.Name != "" {
+		return v.Run.Info.Controller.Name
+	}
+	return "unknown"
+}
+
+func (v *Provider) newCommentTraceLogContext(ctx context.Context, event *info.Event, marker string) commentTraceLogContext {
+	return commentTraceLogContext{
+		dedupTrace:      newDedupTraceID(),
+		eventID:         eventID(event),
+		markerHash:      markerHash(marker),
+		markerLen:       len(marker),
+		controllerLabel: v.controllerLabel(ctx),
+	}
+}
+
+func (v *Provider) debugCommentPhase(event *info.Event, trace commentTraceLogContext, phase string, kv ...any) {
+	if v.Logger == nil {
+		return
+	}
+
+	org := "unknown"
+	repo := "unknown"
+	pr := 0
+	if event != nil {
+		org = event.Organization
+		repo = event.Repository
+		pr = event.PullRequestNumber
+	}
+
+	baseFields := []any{
+		"phase", phase,
+		"organization", org,
+		"repository", repo,
+		"pr", pr,
+		"event_id", trace.eventID,
+		"dedup_trace", trace.dedupTrace,
+		"marker_hash", trace.markerHash,
+		"marker_len", trace.markerLen,
+		"controller_label", trace.controllerLabel,
+	}
+	v.Logger.Debugw("github comment dedup flow", append(baseFields, kv...)...)
+}
+
+func (v *Provider) listCommentsByMarker(
+	ctx context.Context,
+	event *info.Event,
+	marker, phase string,
+	trace commentTraceLogContext,
+) ([]*github.IssueComment, error) {
 	comments, _, err := wrapAPI(v, "list_comments", func() ([]*github.IssueComment, *github.Response, error) {
 		return v.Client().Issues.ListComments(ctx, event.Organization, event.Repository, event.PullRequestNumber, &github.IssueListCommentsOptions{
 			ListOptions: github.ListOptions{
@@ -770,6 +882,13 @@ func (v *Provider) listCommentsByMarker(ctx context.Context, event *info.Event,
 			matchedComments = append(matchedComments, comment)
 		}
 	}
+
+	v.debugCommentPhase(event, trace, phase,
+		"fetched_count", len(comments),
+		"matched_count", len(matchedComments),
+		"matched_comments", compactCommentIDs(matchedComments),
+	)
+
 	return matchedComments, nil
 }
 
@@ -778,11 +897,16 @@ func (v *Provider) ensureSingleMarkerComment(
 	event *info.Event,
 	comments []*github.IssueComment,
 	commit string,
+	trace commentTraceLogContext,
 ) error {
 	if len(comments) == 0 {
 		return nil
 	}
 
+	if len(comments) > 1 {
+		v.debugCommentPhase(event, trace, "duplicate_detected", "matched_count", len(comments))
+	}
+
 	primaryComment := comments[0]
 	for _, comment := range comments {
 		if comment.GetBody() == commit {
@@ -791,6 +915,11 @@ func (v *Provider) ensureSingleMarkerComment(
 		}
 	}
 
+	v.debugCommentPhase(event, trace, "dedup_select_primary",
+		"matched_count", len(comments),
+		"primary_comment_id", primaryComment.GetID(),
+	)
+
 	if primaryComment.GetBody() != commit {
 		if _, _, err := wrapAPI(v, "edit_comment", func() (*github.IssueComment, *github.Response, error) {
 			return v.Client().Issues.EditComment(ctx, event.Organization, event.Repository, primaryComment.GetID(), &github.IssueComment{
@@ -806,14 +935,23 @@ func (v *Provider) ensureSingleMarkerComment(
 		if comment.GetID() == primaryComment.GetID() {
 			continue
 		}
-		if _, _, err := wrapAPI(v, "delete_comment", func() (struct{}, *github.Response, error) {
+
+		v.debugCommentPhase(event, trace, "dedup_delete_attempt", "delete_comment_id", comment.GetID())
+		_, resp, err := wrapAPI(v, "delete_comment", func() (struct{}, *github.Response, error) {
 			resp, err := v.Client().Issues.DeleteComment(ctx, event.Organization, event.Repository, comment.GetID())
 			return struct{}{}, resp, err
-		}); err != nil && v.Logger != nil {
+		})
+		v.debugCommentPhase(event, trace, "dedup_delete_done",
+			"delete_comment_id", comment.GetID(),
+			"status_code", responseStatusCode(resp),
+			"delete_error", err != nil,
+		)
+		if err != nil && v.Logger != nil {
 			v.Logger.Warnf("failed to delete duplicate comment %d on %s/%s#%d: %v",
 				comment.GetID(), event.Organization, event.Repository, event.PullRequestNumber, err)
 		}
 	}
+	v.debugCommentPhase(event, trace, "dedup_complete", "final_expected_count", 1)
 	return nil
 }
 
@@ -827,18 +965,25 @@ func (v *Provider) CreateComment(ctx context.Context, event *info.Event, commit,
 		return fmt.Errorf("create comment only works on pull requests")
 	}
 
+	trace := v.newCommentTraceLogContext(ctx, event, updateMarker)
+
 	if updateMarker != "" {
-		existingComments, err := v.listCommentsByMarker(ctx, event, updateMarker)
+		existingComments, err := v.listCommentsByMarker(ctx, event, updateMarker, "initial_list", trace)
 		if err != nil {
 			return err
 		}
 
+		if len(existingComments) > 1 {
+			v.debugCommentPhase(event, trace, "duplicate_detected", "matched_count", len(existingComments))
+		}
+
 		if len(existingComments) > 0 {
-			return v.ensureSingleMarkerComment(ctx, event, existingComments, commit)
+			return v.ensureSingleMarkerComment(ctx, event, existingComments, commit, trace)
 		}
 
 		//nolint:gosec // No need for crypto/rand here, just reducing timing window
 		jitter := time.Duration(rand.Intn(500)) * time.Millisecond
+		v.debugCommentPhase(event, trace, "jitter_wait", "jitter_ms", jitter.Milliseconds())
 		timer := time.NewTimer(jitter)
 		defer timer.Stop()
 
@@ -849,33 +994,50 @@ func (v *Provider) CreateComment(ctx context.Context, event *info.Event, commit,
 		}
 
 		// Re-check after jitter in case another processor already created the marker comment.
-		existingComments, err = v.listCommentsByMarker(ctx, event, updateMarker)
+		existingComments, err = v.listCommentsByMarker(ctx, event, updateMarker, "post_jitter_list", trace)
 		if err != nil {
 			return err
 		}
+		if len(existingComments) > 1 {
+			v.debugCommentPhase(event, trace, "duplicate_detected", "matched_count", len(existingComments))
+		}
 		if len(existingComments) > 0 {
-			return v.ensureSingleMarkerComment(ctx, event, existingComments, commit)
+			return v.ensureSingleMarkerComment(ctx, event, existingComments, commit, trace)
 		}
+
+		v.debugCommentPhase(event, trace, "pre_create_race_window", "matched_count", len(existingComments))
 	}
 
-	_, _, err := wrapAPI(v, "create_comment", func() (*github.IssueComment, *github.Response, error) {
+	v.debugCommentPhase(event, trace, "create_comment_start")
+	createdComment, createResp, err := wrapAPI(v, "create_comment", func() (*github.IssueComment, *github.Response, error) {
 		return v.Client().Issues.CreateComment(ctx, event.Organization, event.Repository, event.PullRequestNumber, &github.IssueComment{
 			Body: github.Ptr(commit),
 		})
 	})
 	if err != nil {
+		v.debugCommentPhase(event, trace, "create_comment_done",
+			"status_code", responseStatusCode(createResp),
+			"create_error", err.Error(),
+		)
 		return err
 	}
+	v.debugCommentPhase(event, trace, "create_comment_done",
+		"status_code", responseStatusCode(createResp),
+		"created_comment_id", createdComment.GetID(),
+	)
 
 	if updateMarker == "" {
 		return nil
 	}
 
 	// Best-effort post-create reconciliation to collapse duplicates created by
 	// concurrent processors handling the same event.
-	matchedComments, listErr := v.listCommentsByMarker(ctx, event, updateMarker)
+	matchedComments, listErr := v.listCommentsByMarker(ctx, event, updateMarker, "post_create_list", trace)
 	if listErr != nil {
 		return nil
 	}
-	return v.ensureSingleMarkerComment(ctx, event, matchedComments, commit)
+	if len(matchedComments) > 1 {
+		v.debugCommentPhase(event, trace, "duplicate_detected", "matched_count", len(matchedComments))
+	}
+	return v.ensureSingleMarkerComment(ctx, event, matchedComments, commit, trace)
 }