The operator fails over every 30m when sidecar is specified

[haf]

After getting advice, this is a cross post with zalando/spilo#536 — it would seem the fault is with the operator and not Spilo.

• Which image of the operator are you using? registry.opensource.zalan.do/acid/postgres-operator:v1.6.0
• Where do you run it - cloud or metal? Kubernetes or OpenShift? GCP
• Are you running Postgres Operator in production? yes
• Type of issue? bug report

For me it's enough to define a sidecar like this, to trigger the behaviour:

  sidecars:
  - name: exporter
    image: wrouesnel/postgres_exporter

    env:
    - name: "DATA_SOURCE_URI"
      value: app-analytics-db/analytics?sslmode=require

    - name: "DATA_SOURCE_USER"
      valueFrom:
        secretKeyRef:
          name: postgres.app-analytics-db.credentials
          key: username

    - name: "DATA_SOURCE_PASS"
      valueFrom:
        secretKeyRef:
          name: postgres.app-analytics-db.credentials
          key: password

    - name: PG_EXPORTER_WEB_LISTEN_ADDRESS
      value: ":9114"

    - name: PG_EXPORTER_CONSTANT_LABELS
      value: app=analytics-db,component=postgres

    ports:
    - name: http-prom
      containerPort: 9114

    resources:
      limits:
        cpu: 500m
        memory: 256M
      requests:
        cpu: 100m
        memory: 200M

Causes it to fail over every thirty minutes:

Some logs:

time="2021-01-06T17:24:36Z" level=debug msg="metadata.annotation are different" cluster-name=app/app-analytics-db pkg=cluster worker=1
time="2021-01-06T17:24:36Z" level=debug msg="-  zalando-postgres-operator-rolling-update-required: false" cluster-name=app/app-analytics-db pkg=cluster worker=1
time="2021-01-06T17:24:36Z" level=debug msg="+  zalando-postgres-operator-rolling-update-required: true" cluster-name=app/app-analytics-db pkg=cluster worker=1
time="2021-01-06T17:24:36Z" level=info msg="reason: new statefulset containers's exporter (index 1) ports do not match the current one" cluster-name=app/app-analytics-db pkg=cluster worker=1
time="2021-01-06T17:24:36Z" level=debug msg="updating statefulset" cluster-name=app/app-analytics-db pkg=cluster worker=1
time="2021-01-06T17:24:36Z" level=debug msg="patching statefulset annotations" cluster-name=app/app-analytics-db pkg=cluster worker=1
time="2021-01-06T17:24:37Z" level=debug msg="patching statefulset annotations" cluster-name=app/app-analytics-db pkg=cluster worker=1
time="2021-01-06T17:24:37Z" level=debug msg="calling Patroni API on a pod app/app-analytics-db-0 to set the following Postgres options: map[wal_level:logical]" cluster-name=app/app-analytics-db pkg=cluster worker=1
time="2021-01-06T17:24:37Z" level=debug msg="making PATCH http request: http://10.4.7.76:8008/config" cluster-name=app/app-analytics-db pkg=cluster worker=1

[FxKu]

Do you also get pod label wait timeouts? Does it take too long for a new instance to stream from the master? For these cases we aware that the operator might end up redoing rolling updates. On trick could be to scale the operator down to 0 instances, wait till the replica is up an running and bring the operator back. We should finally move this zalando-postgres-operator-rolling-update-required annotation from the statefulset to the pods...

[haf]

@FxKu No pod label wait timeouts, at least neither in the k8s events, nor in the operator logs.

It all works very quickly; the failover is almost instant, but it cancels all the connections, including my restore job.

I've tried completely deleting the database and recreating it, to no avail.

I'm currently trying without the sidecar.

In an offtopic problem, it would seem it never successfully patches the wal_level, is it keeps getting logged again and again:

time="2021-01-06T17:54:36Z" level=debug msg="patching statefulset annotations" cluster-name=app/app-analytics-db pkg=cluster worker=1
time="2021-01-06T17:54:37Z" level=debug msg="calling Patroni API on a pod app/app-analytics-db-0 to set the following Postgres options: map[wal_level:logical]" cluster-name=app/app-analytics-db pkg=cluster worker=1
time="2021-01-06T17:54:37Z" level=debug msg="making PATCH http request: http://10.4.7.78:8008/config" cluster-name=app/app-analytics-db pkg=cluster worker=1

[FxKu]

not sure if there's always a log line when you specify postgres.conf parameters in the manifest. But you can check in the container if it's updated.

[haf]

In any case, it would be great to have my prom exporter...

[FxKu]

From the logs you've posted it looks like the rolling update is triggered due to changing container ports ("ports do not match the current one"). Doesn't it get the 9114 port, but a random one?

[haf]

It says index 1. However, there is only a single port on the exporter.

The port it has is otherwise correct.

[FxKu]

the index applies to the containers. 0 should be postgres, and then 1 is the sidecar container.

[haf]

I think it's because the Istio sidecar gets a port as well; the meta env var from Istio look like this:

      ISTIO_META_POD_PORTS:          [
                                         {"containerPort":8008,"protocol":"TCP"}
                                         ,{"containerPort":5432,"protocol":"TCP"}
                                         ,{"containerPort":8080,"protocol":"TCP"}
                                         ,{"name":"http-prom","containerPort":9114,"protocol":"TCP"}
                                     ]

Similarly, when describing the pod, there are four ports that are listening on it, two istio ones and the exporter and the postgres port, as well.

Perhaps the operator could look for the port by name rather than by index?

[EricPE69]

Hello,

I have the same problem (a sidecar container for prometheus exporter).
The database is ok; the exporter is Ok. But the operator make a rolling upgrade every 30 min.
Same reason:
"reason: new statefulset containers's metrics (index 1) ports do not match the current one"

The only workaround is to increase the resync_period.

Here is the log:

time="2021-01-26T12:47:15Z" level=debug msg="set statefulset's rolling update annotation to false: caller/reason from cache" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="set statefulset's rolling update annotation to true: caller/reason statefulset changes" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=info msg="statefulset testope/acid-testef is not in the desired state and needs to be updated" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- terminationMessagePath: /dev/termination-log," cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- terminationMessagePolicy: File," cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- containerPort: 9187," cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- protocol: TCP" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="+ containerPort: 9187" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- terminationMessagePath: /dev/termination-log," cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- terminationMessagePolicy: File," cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- restartPolicy: Always," cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- dnsPolicy: ClusterFirst," cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- serviceAccount: postgres-pod," cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- }," cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- schedulerName: default-scheduler" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="+ }" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- kind: PersistentVolumeClaim," cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- apiVersion: v1," cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- status: {" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- phase: Pending" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- }" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="+ status: {}" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- }," cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- revisionHistoryLimit: 10" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="+ }" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="metadata.annotation are different" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="- zalando-postgres-operator-rolling-update-required: false" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="+ zalando-postgres-operator-rolling-update-required: true" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=info msg="reason: new statefulset containers's metrics (index 1) ports do not match the current one" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="updating statefulset" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="patching statefulset annotations" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="patching statefulset annotations" cluster-name=testope/acid-testef pkg=cluster time="2021-01-26T12:47:15Z" level=debug msg="performing rolling update" cluster-name=testope/acid-testef pkg=cluster

[FxKu]

When the Ports are compared, their order should indeed not matter. We should use IsEqualIgnoreOrder, but then ContainerPort is a struct. Hm, maybe one of you wants to dive deeper and either optimize the comparison part or find out why the order is always different.

[Ferroman]

I have the same issue with operator v1.16

apiVersion: "acid.zalan.do/v1"
kind: postgresql
metadata:
  name: qa-postgresql
  namespace: qa
spec:
  teamId: "qa"
  volume:
    size: 335Gi
  patroni:
    synchronous_mode: true
  numberOfInstances: 2
  users:
    strapi:  # database owner
    - superuser
    - createdb
  postgresql:
    version: "13"
  sidecars:
    - name: postgres-exporter
      image: wrouesnel/postgres_exporter
      ports:
        - containerPort: 9187
          name: metrics
      env:
        - name: DATASOURCE_URI
          value: "postgresql://localhost:5432/ranger?sslmode=disable"
        - name: DATA_SOURCE_USER
          value: "$(POSTGRES_USER)"
        - name: DATA_SOURCE_PASS
          value: "$(POSTGRES_PASSWORD)"
      resources:
        limits:
          cpu: 50m 
          memory: 150Mi
        requests:
          cpu: 50m
          memory: 150Mi

time="2021-02-16T13:10:02Z" level=debug msg="set statefulset's rolling update annotation to false: caller/reason from cache" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="set statefulset's rolling update annotation to true: caller/reason statefulset changes" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=info msg="statefulset dev/dev-postgresql is not in the desired state and needs to be updated" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-          terminationMessagePath: /dev/termination-log," cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-          terminationMessagePolicy: File," cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-              containerPort: 9187," cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-              protocol: TCP" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="+              containerPort: 9187" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-          terminationMessagePath: /dev/termination-log," cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-          terminationMessagePolicy: File," cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-      restartPolicy: Always," cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-      dnsPolicy: ClusterFirst," cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-      serviceAccount: postgres-pod," cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-      securityContext: {}," cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-      schedulerName: default-scheduler" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="+      securityContext: {}" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-      kind: PersistentVolumeClaim," cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-      apiVersion: v1," cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-      status: {" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-        phase: Pending" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-      }" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="+      status: {}" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-  }," cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-  revisionHistoryLimit: 10" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="+  }" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="metadata.annotation are different" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="-  zalando-postgres-operator-rolling-update-required: false" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=debug msg="+  zalando-postgres-operator-rolling-update-required: true" cluster-name=dev/dev-postgresql pkg=cluster
time="2021-02-16T13:10:02Z" level=info msg="reason: new statefulset containers's postgres-exporter (index 1) ports do not match the current one" cluster-name=dev/dev-postgresql pkg=cluster

Is there any workaround to ignore port changes or something?

[FxKu]

I've hacked the operator to give me more details on why the ports are different and look what I've found:

reason: new statefulset containers's postgres-exporter (index 1) ports do not match the current one: 
[]v1.ContainerPort{v1.ContainerPort{Name:\"metrics\", HostPort:0, ContainerPort:9187, Protocol:\"TCP\", HostIP:\"\"}} vs
[]v1.ContainerPort{v1.ContainerPort{Name:\"metrics\", HostPort:0, ContainerPort:9187, Protocol:\"\", HostIP:\"\"}}

Seems that the TCP protocol is assigned by default by K8s. If you add Protocol: TCP in the manifest there will be no diff and rolling updates will stop.

[FxKu]

@haf @EricPE69 @Ferroman 😃