watcher: shared EventEmitter logger mis-attributes log lines across concurrent reconciles

[chmouel]

Reconciler.eventEmitter is a *events.EventEmitter shared by every reconcile in the watcher. ReconcileKind copies the Reconciler struct and params.Run per reconcile, but copying a struct copies the pointer, so every concurrent reconcile keeps writing to the same emitter.

reconcileKind then swaps that emitter's logger in place:

https://github.com/tektoncd/pipelines-as-code/blob/main/pkg/reconciler/reconciler.go#L265

SetLogger is an unsynchronised assignment:

https://github.com/tektoncd/pipelines-as-code/blob/main/pkg/events/emit.go#L29-L31

knative runs DefaultThreadsPerController = 2 workers per controller, so reconciles overlap. That leaves us with a data race on EventEmitter.logger, and with any EmitMessage that fires before line 265 in its own reconcile being logged under fields another reconcile installed.

The git-auth secret warning fires well before it:

https://github.com/tektoncd/pipelines-as-code/blob/main/pkg/reconciler/reconciler.go#L314

so it always borrows someone else's logger. A user hit this and read the result as a cross-namespace credential leak:

msg: "Secret pac-gitauth-xxxxxx already exists in namespace ns-b, reusing existing secret"
namespace: ns-a
knative.dev/key: ns-a/some-pipelinerun
source-repo-url: https://git.example.com/org/repo

Nothing crossed namespaces. The message text is built from repo.GetNamespace() of a reconcile in ns-b, while the fields belong to a reconcile in ns-a. The two halves are separable because source-repo-url, target-branch and event-type are only attached in the "pipelinerun is done, report status" block, right before SetLogger:

https://github.com/tektoncd/pipelines-as-code/blob/main/pkg/reconciler/reconciler.go#L240-L263

That same call also passes a nil Repository, so we record no Event on the Repository CR and the mangled log line is the only trace anyone gets.

Reproducer

Drop this in pkg/reconciler/ and run go test ./pkg/reconciler/ -run TestSecretReuseLogAttribution -v. It installs a logger with reconcile A's fields on the shared emitter, then runs createSecretForPipelineRun for a Repository in another namespace whose CreateSecret returns AlreadyExists:

MSG="Secret pac-gitauth-xxxxxx already exists in namespace ns-b, reusing existing secret"
FIELDS=map[namespace:ns-a pipeline-run:some-pipelinerun source-repo-url:https://git.example.com/org/repo]

test file

type alreadyExistsKint struct {
	*testkubernetesint.KinterfaceTest
}

func (a *alreadyExistsKint) CreateSecret(_ context.Context, ns string, secret *corev1.Secret) error {
	return errors.NewAlreadyExists(schema.GroupResource{Resource: "secrets"}, ns+"/"+secret.GetName())
}

func TestSecretReuseLogAttribution(t *testing.T) {
	ctx, _ := rtesting.SetupFakeContext(t)
	ctx = info.StoreNS(ctx, system.Namespace())
	observer, logCatcher := zapobserver.New(zap.InfoLevel)
	baseLogger := zap.New(observer).Sugar()

	repo := &v1alpha1.Repository{
		ObjectMeta: metav1.ObjectMeta{Name: "repo-b", Namespace: "ns-b"},
		Spec: v1alpha1.RepositorySpec{
			URL: "https://github.com/org/repo-b",
			GitProvider: &v1alpha1.GitProvider{
				URL:    "https://github.com",
				Secret: &v1alpha1.Secret{Name: "provider-secret"},
			},
		},
	}
	pr := &tektonv1.PipelineRun{
		ObjectMeta: metav1.ObjectMeta{
			Name:      "repo-b-run",
			Namespace: "ns-b",
			Annotations: map[string]string{
				keys.GitProvider:   "github",
				keys.RepoURL:       "https://github.com/org/repo-b",
				keys.URLOrg:        "org",
				keys.URLRepository: "repo-b",
				keys.SHA:           "deadbeef",
				keys.GitAuthSecret: "pac-gitauth-xxxxxx",
			},
		},
	}
	stdata, informers := testclient.SeedTestData(t, ctx, testclient.Data{
		Repositories: []*v1alpha1.Repository{repo},
		ConfigMap:    []*corev1.ConfigMap{defaultPolicyConfigMap()},
	})

	r := &Reconciler{
		repoLister: informers.Repository.Lister(),
		kinteract: &alreadyExistsKint{KinterfaceTest: &testkubernetesint.KinterfaceTest{
			GetSecretResult: map[string]string{"provider-secret": "test-token"},
		}},
		eventEmitter: events.NewEventEmitter(stdata.Kube, baseLogger),
		run: &params.Run{
			Clients: clients.Clients{
				Kube:           stdata.Kube,
				PipelineAsCode: stdata.PipelineAsCode,
				Tekton:         stdata.Pipeline,
				Log:            baseLogger,
			},
			Info: info.Info{
				Kube:       &info.KubeOpts{Namespace: "global"},
				Controller: &info.ControllerInfo{GlobalRepository: "global-repo"},
				Pac:        info.NewPacOpts(),
			},
		},
	}

	// reconcile A reaches reconciler.go:265 and installs its logger on the shared emitter
	r.eventEmitter.SetLogger(baseLogger.With(
		"namespace", "ns-a",
		"pipeline-run", "some-pipelinerun",
		"source-repo-url", "https://git.example.com/org/repo",
	))

	// reconcile B, in ns-b, hits AlreadyExists
	cachedRepo, err := informers.Repository.Lister().Repositories(repo.Namespace).Get(repo.Name)
	if err != nil {
		t.Fatal(err)
	}
	_ = r.createSecretForPipelineRun(ctx, baseLogger, pr, cachedRepo)

	for _, entry := range logCatcher.TakeAll() {
		t.Logf("MSG=%q FIELDS=%v", entry.Message, entry.ContextMap())
	}
}

Suggested fix

Give each reconcile its own emitter rather than mutating the shared one. A func (e *EventEmitter) WithLogger(l *zap.SugaredLogger) *EventEmitter returning a copy would do, used locally in reconcileKind and set up early enough that the secret path gets its own PipelineRun's context.

Two smaller things on the same line: put the PipelineRun namespace and name in the message so it stands on its own, and pass repo instead of nil so the Warning Event lands on the Repository CR that hit the condition.

Goes back at least to v0.48.1, which ships in OpenShift Pipelines 1.23 (reconciler.go:185 and :234 there).

[chmouel]

Tracked downstream as https://issues.redhat.com/browse/SRVKP-14117