CI fluke: two pods created for a ReplicaSet with one replica

[dtantsur]

Observed in https://github.com/metal3-io/ironic-standalone-operator/actions/runs/16174585591/attempts/1?pr=303

Two Ironic pods are created, both progress normally since they are on different nodes. The tests blow up because of httpd being not ready in one of them, but it's possible that more instances of the same problem happen without a failure.

Relevant kube-scheduler logs:

I0709 16:44:28.771186       1 cache.go:504] "Pod was added to a different node than it was assumed" podKey="6503fbad-ccc5-4ea7-babc-9b68132dfc9b" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-f7bcs" assumedNode="minikube" currentNode="minikube-m03"
I0709 16:44:28.788794       1 cache.go:504] "Pod was added to a different node than it was assumed" podKey="ac1a8982-0dfc-46da-a5cb-6dfde9ca5e99" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-8lzrh" assumedNode="minikube-m03" currentNode="minikube"
I0709 16:44:28.812594       1 cache.go:504] "Pod was added to a different node than it was assumed" podKey="0fba088b-7c02-4a37-91f7-1c6eccfb6deb" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-ntzxt" assumedNode="minikube-m02" currentNode="minikube-m03"
E0709 16:44:28.830483       1 framework.go:1317] "Plugin Failed" err="Operation cannot be fulfilled on pods/binding \"test-ironic-service-d9cb7cbb7-f7bcs\": pod test-ironic-service-d9cb7cbb7-f7bcs is already assigned to node \"minikube\"" plugin="DefaultBinder" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-f7bcs" node="minikube-m03"
E0709 16:44:28.830792       1 schedule_one.go:347] "scheduler cache ForgetPod failed" err="pod 6503fbad-ccc5-4ea7-babc-9b68132dfc9b(test-disabled-downloader/test-ironic-service-d9cb7cbb7-f7bcs) was assumed on minikube-m03 but assigned to minikube" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-f7bcs"
E0709 16:44:28.831020       1 schedule_one.go:1046] "Error scheduling pod; retrying" err="running Bind plugin \"DefaultBinder\": Operation cannot be fulfilled on pods/binding \"test-ironic-service-d9cb7cbb7-f7bcs\": pod test-ironic-service-d9cb7cbb7-f7bcs is already assigned to node \"minikube\"" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-f7bcs"
E0709 16:44:28.830670       1 framework.go:1317] "Plugin Failed" err="Operation cannot be fulfilled on pods/binding \"test-ironic-service-d9cb7cbb7-8lzrh\": pod test-ironic-service-d9cb7cbb7-8lzrh is already assigned to node \"minikube-m03\"" plugin="DefaultBinder" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-8lzrh" node="minikube"
E0709 16:44:28.831060       1 schedule_one.go:347] "scheduler cache ForgetPod failed" err="pod ac1a8982-0dfc-46da-a5cb-6dfde9ca5e99(test-disabled-downloader/test-ironic-service-d9cb7cbb7-8lzrh) was assumed on minikube but assigned to minikube-m03" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-8lzrh"
E0709 16:44:28.831074       1 schedule_one.go:1046] "Error scheduling pod; retrying" err="running Bind plugin \"DefaultBinder\": Operation cannot be fulfilled on pods/binding \"test-ironic-service-d9cb7cbb7-8lzrh\": pod test-ironic-service-d9cb7cbb7-8lzrh is already assigned to node \"minikube-m03\"" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-8lzrh"
I0709 16:44:28.831090       1 schedule_one.go:1059] "Pod has been assigned to node. Abort adding it back to queue." pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-8lzrh" node="minikube-m03"
I0709 16:44:28.831050       1 schedule_one.go:1059] "Pod has been assigned to node. Abort adding it back to queue." pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-f7bcs" node="minikube"
E0709 16:44:28.830613       1 framework.go:1317] "Plugin Failed" err="Operation cannot be fulfilled on pods/binding \"test-ironic-service-d9cb7cbb7-ntzxt\": pod test-ironic-service-d9cb7cbb7-ntzxt is already assigned to node \"minikube-m02\"" plugin="DefaultBinder" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-ntzxt" node="minikube-m03"
E0709 16:44:28.832189       1 schedule_one.go:347] "scheduler cache ForgetPod failed" err="pod 0fba088b-7c02-4a37-91f7-1c6eccfb6deb(test-disabled-downloader/test-ironic-service-d9cb7cbb7-ntzxt) was assumed on minikube-m03 but assigned to minikube-m02" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-ntzxt"
E0709 16:44:28.832328       1 schedule_one.go:1046] "Error scheduling pod; retrying" err="running Bind plugin \"DefaultBinder\": Operation cannot be fulfilled on pods/binding \"test-ironic-service-d9cb7cbb7-ntzxt\": pod test-ironic-service-d9cb7cbb7-ntzxt is already assigned to node \"minikube-m02\"" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-ntzxt"
I0709 16:44:28.832665       1 schedule_one.go:1059] "Pod has been assigned to node. Abort adding it back to queue." pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-ntzxt" node="minikube-m02"
E0709 16:44:30.229970       1 framework.go:1317] "Plugin Failed" err="Operation cannot be fulfilled on pods/binding \"test-ironic-service-d9cb7cbb7-j6sr2\": pod test-ironic-service-d9cb7cbb7-j6sr2 is already assigned to node \"minikube-m02\"" plugin="DefaultBinder" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-j6sr2" node="minikube-m02"
E0709 16:44:30.230018       1 schedule_one.go:347] "scheduler cache ForgetPod failed" err="pod aa4dcca3-ed79-442e-a2ab-a00cc7a4f9b4(test-disabled-downloader/test-ironic-service-d9cb7cbb7-j6sr2) wasn't assumed so cannot be forgotten" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-j6sr2"
E0709 16:44:30.230057       1 schedule_one.go:1046] "Error scheduling pod; retrying" err="running Bind plugin \"DefaultBinder\": Operation cannot be fulfilled on pods/binding \"test-ironic-service-d9cb7cbb7-j6sr2\": pod test-ironic-service-d9cb7cbb7-j6sr2 is already assigned to node \"minikube-m02\"" pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-j6sr2"
I0709 16:44:30.230079       1 schedule_one.go:1059] "Pod has been assigned to node. Abort adding it back to queue." pod="test-disabled-downloader/test-ironic-service-d9cb7cbb7-j6sr2" node="minikube-m02"

I think a similar problem may be affecting the upgrade jobs but I have no proofs of that.

[metal3-io-bot]

This issue is currently awaiting triage.
If Metal3.io contributors determine this is a relevant issue, they will accept it by applying the triage/accepted label and provide further guidance.
The triage/accepted label can be added by org members by writing /triage accepted in a comment.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

[dtantsur]

functional-regular.zip - copy of the logs in case the job gets garbage collected. Look for test-disabled-downloader.

[dtantsur]

The deployment (without managedFields):

metadata:
  annotations:
    deployment.kubernetes.io/revision: "1"
  creationTimestamp: "2025-07-09T16:44:28Z"
  generation: 1
  labels:
    ironic.metal3.io/ironic: test-ironic
    ironic.metal3.io/version: latest
  name: test-ironic-service
  namespace: test-disabled-downloader
  ownerReferences:
  - apiVersion: ironic.metal3.io/v1alpha1
    blockOwnerDeletion: true
    controller: true
    kind: Ironic
    name: test-ironic
    uid: 7caa2c93-0147-4163-aaf3-5b53fbee1e1c
  resourceVersion: "10091"
  uid: 68917265-0049-42dc-8cd5-11ffa7f6e284
spec:
  progressDeadlineSeconds: 600
  replicas: 1
  revisionHistoryLimit: 10
  selector:
    matchLabels:
      ironic.metal3.io/app: test-ironic-service
  strategy:
    type: Recreate
  template:
    metadata:
      annotations:
        ironic.metal3.io/api-secret-version: 7cb9cfbf-9b03-4b5d-b8f4-11cdf8f70fe6/9878
      creationTimestamp: null
      labels:
        ironic.metal3.io/app: test-ironic-service
        ironic.metal3.io/ironic: test-ironic
        ironic.metal3.io/version: latest
    spec:
      containers:
      - command:
        - /bin/runironic
        env:
        - name: IRONIC_LISTEN_PORT
          value: "6385"
        - name: HTTP_PORT
          value: "6180"
        - name: LISTEN_ALL_INTERFACES
          value: "true"
        - name: USE_IRONIC_INSPECTOR
          value: "false"
        - name: PROVISIONING_IP
          valueFrom:
            fieldRef:
              apiVersion: v1
              fieldPath: status.hostIP
        - name: IRONIC_USE_MARIADB
          value: "false"
        - name: IRONIC_EXPOSE_JSON_RPC
          value: "false"
        - name: IRONIC_HTPASSWD
          valueFrom:
            secretKeyRef:
              key: htpasswd
              name: test-ironic-service-pcf7z
        image: quay.io/metal3-io/ironic:latest
        imagePullPolicy: Always
        livenessProbe:
          exec:
            command:
            - curl
            - --head
            - --insecure
            - --location
            - --silent
            - --show-error
            - --output
            - /dev/null
            - --fail
            - http://127.0.0.1:6385/v1
          failureThreshold: 12
          initialDelaySeconds: 1
          periodSeconds: 10
          successThreshold: 1
          timeoutSeconds: 5
        name: ironic
        ports:
        - containerPort: 6385
          hostPort: 6385
          name: ironic-api
          protocol: TCP
        readinessProbe:
          exec:
            command:
            - curl
            - --head
            - --insecure
            - --location
            - --silent
            - --show-error
            - --output
            - /dev/null
            - --fail
            - http://127.0.0.1:6385/v1
          failureThreshold: 12
          initialDelaySeconds: 1
          periodSeconds: 10
          successThreshold: 1
          timeoutSeconds: 5
        resources: {}
        securityContext:
          capabilities:
            drop:
            - ALL
          runAsGroup: 994
          runAsUser: 997
        terminationMessagePath: /dev/termination-log
        terminationMessagePolicy: File
        volumeMounts:
        - mountPath: /shared
          name: ironic-shared
      - command:
        - /bin/runhttpd
        env:
        - name: IRONIC_LISTEN_PORT
          value: "6385"
        - name: HTTP_PORT
          value: "6180"
        - name: LISTEN_ALL_INTERFACES
          value: "true"
        - name: USE_IRONIC_INSPECTOR
          value: "false"
        - name: PROVISIONING_IP
          valueFrom:
            fieldRef:
              apiVersion: v1
              fieldPath: status.hostIP
        image: quay.io/metal3-io/ironic:latest
        imagePullPolicy: Always
        livenessProbe:
          exec:
            command:
            - curl
            - --head
            - --insecure
            - --location
            - --silent
            - --show-error
            - --output
            - /dev/null
            - http://127.0.0.1:6180/images/ironic-python-agent.kernel
          failureThreshold: 12
          initialDelaySeconds: 1
          periodSeconds: 10
          successThreshold: 1
          timeoutSeconds: 5
        name: httpd
        ports:
        - containerPort: 6180
          hostPort: 6180
          name: image-svc
          protocol: TCP
        readinessProbe:
          exec:
            command:
            - curl
            - --head
            - --insecure
            - --location
            - --silent
            - --show-error
            - --output
            - /dev/null
            - http://127.0.0.1:6180/images/ironic-python-agent.kernel
          failureThreshold: 12
          initialDelaySeconds: 1
          periodSeconds: 10
          successThreshold: 1
          timeoutSeconds: 5
        resources: {}
        securityContext:
          capabilities:
            drop:
            - ALL
          runAsGroup: 994
          runAsUser: 997
        terminationMessagePath: /dev/termination-log
        terminationMessagePolicy: File
        volumeMounts:
        - mountPath: /shared
          name: ironic-shared
      - command:
        - /bin/runlogwatch.sh
        image: quay.io/metal3-io/ironic:latest
        imagePullPolicy: Always
        name: ramdisk-logs
        resources: {}
        securityContext:
          capabilities:
            drop:
            - ALL
          runAsGroup: 994
          runAsUser: 997
        terminationMessagePath: /dev/termination-log
        terminationMessagePolicy: File
        volumeMounts:
        - mountPath: /shared
          name: ironic-shared
      dnsPolicy: ClusterFirstWithHostNet
      hostNetwork: true
      restartPolicy: Always
      schedulerName: default-scheduler
      securityContext: {}
      terminationGracePeriodSeconds: 30
      volumes:
      - emptyDir: {}
        name: ironic-shared
      - name: ironic-auth
        secret:
          defaultMode: 420
          secretName: test-ironic-service-pcf7z
status:
  availableReplicas: 1
  conditions:
  - lastTransitionTime: "2025-07-09T16:44:45Z"
    lastUpdateTime: "2025-07-09T16:44:45Z"
    message: Deployment has minimum availability.
    reason: MinimumReplicasAvailable
    status: "True"
    type: Available
  - lastTransitionTime: "2025-07-09T16:44:28Z"
    lastUpdateTime: "2025-07-09T16:44:45Z"
    message: ReplicaSet "test-ironic-service-d9cb7cbb7" has successfully progressed.
    reason: NewReplicaSetAvailable
    status: "True"
    type: Progressing
  observedGeneration: 1
  readyReplicas: 1
  replicas: 1
  updatedReplicas: 1

[dtantsur]

$ grep -E '(Created|Deleted) pod' events.yaml 
message: 'Created pod: test-ironic-service-d9cb7cbb7-8lzrh'
message: 'Deleted pod: test-ironic-service-d9cb7cbb7-8lzrh'
message: 'Deleted pod: test-ironic-service-d9cb7cbb7-ntzxt'
message: 'Created pod: test-ironic-service-d9cb7cbb7-f7bcs'
message: 'Created pod: test-ironic-service-d9cb7cbb7-ntzxt'
message: 'Created pod: test-ironic-service-d9cb7cbb7-j6sr2'
message: 'Deleted pod: test-ironic-service-d9cb7cbb7-f7bcs'

So it tries to create 4 pods (for 1 replica!), then deletes 3 of them. 2 are gone by the time the tests are running, one if left with

  creationTimestamp: "2025-07-09T16:44:28Z"
  deletionGracePeriodSeconds: 30
  deletionTimestamp: "2025-07-09T16:44:58Z"

The test failed at 16:44:49.212.