tektoncd / tektoncd/pipelines-as-code

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

Open
#2,955 1 comment 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

bug
Dominant language
Go
Stars
214
Forks
144
Avg merge
2d 11h
Merged PRs (30d)
27

Description

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).

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with pkg/reconciler/reconciler.go around lines 240-314 and pkg/events/emit.go, especially SetLogger. Add the TestSecretReuseLogAttribution reproducer under pkg/reconciler/ and run go test ./pkg/reconciler/ -run TestSecretReuseLogAttribution -v. Done means concurrent reconciles keep their log context separate, the secret warning identifies its PipelineRun, and the Repository receives the Warning Event.

Written by the indexing model from the issue text.

Assessment

Tech stack
go, kubernetes
Domain
backend, distributed-systems, observability
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Active
Clarity
Clearly specified
Newbie friendliness
68/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.