tektoncd / tektoncd/pipelines-as-code
watcher: shared EventEmitter logger mis-attributes log lines across concurrent reconciles
Nobody has claimed this yet.
- 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: ¶ms.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
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- 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