Realtime Compositions: cannot list in CompositionRevision handler

[paulvonallwoerden]

What happened?

Using the flag --enable-realtime-compositions causes crossplane to stop working. The pod won't crash but it's just not reacting to creating/editing claims. Also, there are error logs that aren't present if the flag is omitted.

$ kubectl logs -n crossplane-system -f crossplane-5fddf49df6-grt4c
{"level":"info","ts":"2024-04-01T22:04:35Z","logger":"crossplane","msg":"Beta feature enabled","flag":"EnableBetaCompositionFunctions"}
{"level":"info","ts":"2024-04-01T22:04:35Z","logger":"crossplane","msg":"Beta feature enabled","flag":"EnableBetaCompositionFunctionsExtraResources"}
{"level":"info","ts":"2024-04-01T22:04:35Z","logger":"crossplane","msg":"Beta feature enabled","flag":"EnableBetaCompositionWebhookSchemaValidation"}
{"level":"info","ts":"2024-04-01T22:04:35Z","logger":"crossplane","msg":"Alpha feature enabled","flag":"EnableAlphaRealtimeCompositions"}
{"level":"info","ts":"2024-04-01T22:04:35Z","logger":"crossplane","msg":"Beta feature enabled","flag":"EnableBetaDeploymentRuntimeConfigs"}
I0401 22:04:37.388729       1 leaderelection.go:250] attempting to acquire leader lease crossplane-system/crossplane-leader-election-core...
I0401 22:04:41.638798       1 leaderelection.go:260] successfully acquired lease crossplane-system/crossplane-leader-election-core
Warning: ControllerConfig.pkg.crossplane.io/v1alpha1 is deprecated. Use DeploymentRuntimeConfig from pkg.crossplane.io/v1beta1 instead.
{"level":"info","ts":"2024-04-01T22:04:42Z","logger":"crossplane","msg":"cannot list in CompositionRevision handler","controller":"defined/compositeresourcedefinition.apiextensions.crossplane.io","type":"somewhere.cloud/v1, Kind=MyStorage","error":"Timeout: failed waiting for *unstructured.Unstructured Informer to sync"}
W0401 22:04:42.400546       1 reflector.go:462] k8s.io/client-go@v0.29.1/tools/cache/reflector.go:229: watch of somewhere.cloud/v1, Kind=MyStorage ended with: an error on the server ("unable to decode an event from the watch stream: context canceled") has prevented the request from succeeding
{"level":"info","ts":"2024-04-01T22:04:42Z","logger":"crossplane","msg":"cannot list in CompositionRevision handler","controller":"defined/compositeresourcedefinition.apiextensions.crossplane.io","type":"somewhere.cloud/v1, Kind=MyStorage","error":"Timeout: failed waiting for *unstructured.Unstructured Informer to sync"}
{"level":"info","ts":"2024-04-01T22:04:42Z","logger":"crossplane","msg":"cannot list in CompositionRevision handler","controller":"defined/compositeresourcedefinition.apiextensions.crossplane.io","type":"somewhere.cloud/v1, Kind=MyStorage","error":"Timeout: failed waiting for *unstructured.Unstructured Informer to sync"}
{"level":"info","ts":"2024-04-01T22:04:42Z","logger":"crossplane","msg":"cannot list in CompositionRevision handler","controller":"defined/compositeresourcedefinition.apiextensions.crossplane.io","type":"somewhere.cloud/v1, Kind=MyStorage","error":"Timeout: failed waiting for *unstructured.Unstructured Informer to sync"}
{"level":"info","ts":"2024-04-01T22:04:42Z","logger":"crossplane","msg":"cannot list in CompositionRevision handler","controller":"defined/compositeresourcedefinition.apiextensions.crossplane.io","type":"somewhere.cloud/v1, Kind=MyStorage","error":"Timeout: failed waiting for *unstructured.Unstructured Informer to sync"}
{"level":"info","ts":"2024-04-01T22:04:42Z","logger":"crossplane","msg":"cannot list in CompositionRevision handler","controller":"defined/compositeresourcedefinition.apiextensions.crossplane.io","type":"somewhere.cloud/v1, Kind=MyStorage","error":"Timeout: failed waiting for *unstructured.Unstructured Informer to sync"}
{"level":"info","ts":"2024-04-01T22:04:42Z","logger":"crossplane","msg":"cannot list in CompositionRevision handler","controller":"defined/compositeresourcedefinition.apiextensions.crossplane.io","type":"somewhere.cloud/v1, Kind=MyStorage","error":"Timeout: failed waiting for *unstructured.Unstructured Informer to sync"}
{"level":"info","ts":"2024-04-01T22:04:42Z","logger":"crossplane","msg":"cannot list in CompositionRevision handler","controller":"defined/compositeresourcedefinition.apiextensions.crossplane.io","type":"somewhere.cloud/v1, Kind=MyStorage","error":"Timeout: failed waiting for *unstructured.Unstructured Informer to sync"}
{"level":"info","ts":"2024-04-01T22:04:42Z","logger":"crossplane","msg":"cannot list in CompositionRevision handler","controller":"defined/compositeresourcedefinition.apiextensions.crossplane.io","type":"somewhere.cloud/v1, Kind=MyStorage","error":"Timeout: failed waiting for *unstructured.Unstructured Informer to sync"}
{"level":"info","ts":"2024-04-01T22:04:42Z","logger":"crossplane","msg":"cannot list in CompositionRevision handler","controller":"defined/compositeresourcedefinition.apiextensions.crossplane.io","type":"somewhere.cloud/v1, Kind=MyStorage","error":"Timeout: failed waiting for *unstructured.Unstructured Informer to sync"}
{"level":"info","ts":"2024-04-01T22:04:42Z","logger":"crossplane","msg":"cannot list in CompositionRevision handler","controller":"defined/compositeresourcedefinition.apiextensions.crossplane.io","type":"somewhere.cloud/v1, Kind=MyStorage","error":"Timeout: failed waiting for *unstructured.Unstructured Informer to sync"}

The relevant code hints at a programming mistake in the crossplane code:

crossplane/internal/controller/apiextensions/composite/reconciler.go

Lines 752 to 753 in d35ecef

	// logging is most we can do here. This is a programming error if it happens.
	log.Info("cannot list in CompositionRevision handler", "type", schema.GroupVersionKind(of).String(), "error", err)

To me it looks a bit suspicious, that the logs mention a timeout but the timestamp of the logs are all the same. Maybe this timeout needs to be configured differently?

How can we reproduce it?

1. Install crossplane using helm with:

# values.yaml
args:
  - '--enable-realtime-compositions'

2. Create the following CompositeResourceDefinition:

CompositeResourceDefinition: MyStorage

apiVersion: apiextensions.crossplane.io/v1
kind: CompositeResourceDefinition
metadata:
  name: mystorages.somewhere.cloud
  namespace: crossplane-system
spec:
  group: somewhere.cloud
  names:
    kind: MyStorage
    plural: mystorages
  versions:
    - name: v1
      served: true
      referenceable: true
      schema:
        openAPIV3Schema:
          type: object
          properties:
            spec:
              type: object
              properties:
                diskName:
                  type: string
            status:
              type: object
              properties:
                bucketUrl:
                  type: string
                websiteUrl:
                  type: string
                userEmail:
                  type: string

I could imagine that this is an issue that may is more specific. The only information I really provide here is my CompositeResourceDefinition. Please tell me what information you need to find the root cause of this issue. I am willing to share more.

What environment did it happen in?

• Crossplane version: 1.15.1
  • repoURL: https://charts.crossplane.io/stable
  • chart: crossplane
• Kubernetes version: v1.29.2 (with kind v0.22.0)
• MacOS 14.2.1
• Darwin Kernel Version 23.2.0

[negz]

CC @sttts, @haarchri

[jbw976]

I've added this issue for tracking to:

• Promote Realtime Compositions to Beta #4828

[jingav]

I'm adding our 50 cents to this as well.

We have experienced a weird behavior and random success/failure ratio on repeated tests when applying Claims that created various (nested) compositions/composite resources (XRs) and multiple MRs while having Realtime compositions enabled.

Symptoms

• various XRs randomly without events, status (empty SYNCED, READY) => sometimes adding/removing crossplane.io/paused: "true" or any change (comment something out) in Composition helped to "retrigger" reconciliation
• randomly missing compositionRef or more often compositionRevisionRef (updatePolicy: Automatic) on hanging XRs
• repeating tapestry of errors for various Kinds in crossplane logs

Examples

 reflector.go:462] k8s.io/client-go@v0.29.1/tools/cache/reflector.go:229: watch of s3control.aws.upbound.io/v1beta1, Kind=AccountPublicAccessBlock ended with: an error on the server ("unable to decode an event from the watch stream: context canceled") has prevented the request from succeeding

something about "cannot read from cache" or "failed creating a cache" or something similar
# cannot get it again after disabling and enable Realtime composition feature

#there is usually this, e.g.
crossplane      Composed resource cache synced  {"controller": "defined/compositeresourcedefinition.apiextensions.crossplane.io", "gvk": "apiextensions.crossplane.io/v1alpha1, Kind=EnvironmentConfig"}

It took some time to track it down to this.
Adding this here to help others troubleshooting this faster.

[negz]

It's possible #5651 might fix this. It's a pretty big rework of realtime compositions. If someone could try to reproduce this issue with that PR, it would be very useful.