Project: scheduled-pg pod hanging and then failed

[yazfaz]

This issue was also posted in the Slack channel

Scheduled snapshots stopped running for all KubeDB databases in my cluster. Updating the Postgres version and KubeDB operator fixed the issue for all applications in the cluster except for one. We have the same set up for 3 other namespaces in the cluster. With a kubedb postgres and 3 scheduled-pg pods. They were working fine after the update. It is only the one namespace which failed. The failing namespace had a scheduled-pg-0 pod that was hanging and eventually failed. I deleted the pod and it failed to come back up.

The issue was eventually resolved by removing KubeDB from the namespace and restoring the database from a manual backup. I'd like to know the cause of this issue to prevent it in the future, as this is on a production environment.

When the scheduled-pg pod was hanging, it had this status:

Status:
  Observed Generation:  4$4215184848040632782
  Phase:                Running
  Reason:               roles.rbac.authorization.k8s.io "scheduled-pg" is forbidden: attempt to grant extra privileges: [{[use] [policy] [podsecuritypolicies] [] []}] user=&{system:serviceaccount:kube-system:kubedb-operator faad96e0-4673-11e9-af74-02a4c44d01ce [system:serviceaccounts system:serviceaccounts:kube-system system:authenticated] map[]} ownerrules=[{[*] [apiextensions.k8s.io] [customresourcedefinitions] [] []} {[get patch] [apiregistration.k8s.io] [apiservices] [] []} {[delete get list watch patch] [admissionregistration.k8s.io] [mutatingwebhookconfigurations validatingwebhookconfigurations] [] []} {[create delete get patch] [rbac.authorization.k8s.io] [rolebindings roles] [] []} {[create delete get patch list] [] [services] [] []} {[create delete get patch] [] [secrets serviceaccounts] [] []} {[create delete get patch update] [apps] [deployments statefulsets] [] []} {[get] [apps] [replicasets] [] []} {[create delete get list watch] [batch] [jobs] [] []} {[get] [storage.k8s.io] [storageclasses] [] []} {[*] [] [pods] [] []} {[create delete get list patch watch] [] [persistentvolumeclaims] [] []} {[create delete get update list patch] [] [configmaps] [] []} {[create] [] [events] [] []} {[get list watch] [] [nodes] [] []} {[*] [kubedb.com catalog.kubedb.com authorization.kubedb.com] [*] [] []} {[*] [appcatalog.appscode.com] [*] [] []} {[*] [monitoring.coreos.com] [servicemonitors] [] []} {[create] [] [pods/exec] [] []} {[list] [apps] [deployments] [] []} {[list] [apps] [statefulsets] [] []} {[use] [policy] [podsecuritypolicies] [kubedb-operator] []} {[use] [policy] [podsecuritypolicies] [elasticsearch-db] []} {[use] [policy] [podsecuritypolicies] [etcd-db] []} {[use] [policy] [podsecuritypolicies] [memcached-db] []} {[use] [policy] [podsecuritypolicies] [mongodb-db] []} {[use] [policy] [podsecuritypolicies] [mysql-db] []} {[use] [policy] [podsecuritypolicies] [postgres-db] []} {[use] [policy] [podsecuritypolicies] [redis-db] []} {[use] [policy] [podsecuritypolicies] [elasticsearch-snapshot] []} {[use] [policy] [podsecuritypolicies] [mongodb-snapshot] []} {[use] [policy] [podsecuritypolicies] [mysql-snapshot] []} {[use] [policy] [podsecuritypolicies] [postgres-snapshot] []} {[create] [authentication.k8s.io] [tokenreviews] [] []} {[create] [authorization.k8s.io] [subjectaccessreviews] [] []} {[create] [authorization.k8s.io] [selfsubjectaccessreviews selfsubjectrulesreviews] [] []} {[get] [] [] [] [/api /api/* /apis /apis/* /healthz /openapi /openapi/* /swagger-2.0.0.pb-v1 /swagger.json /swaggerapi /swaggerapi/* /version /version/]}] ruleResolutionErrors=[]
Events:                 <none>

The logs from the kubedb-operator show::

E0406 00:53:37.367751       1 worker.go:76] Failed to process key assay-upload-manager-10039527/scheduled-pg. Reason: timed out waiting for the condition
I0406 00:53:37.367835       1 worker.go:80] Error syncing key assay-upload-manager-10039527/scheduled-pg: timed out waiting for the condition
I0406 00:53:37.520431       1 statefulset.go:59] Patching StatefulSet assay-upload-manager-10039527/scheduled-pg with {"spec":{"template":{"spec":{"$setElementOrder/containers":[{"name":"postgres"}],"containers":[{"$setElementOrder/env":[{"name":"APPSCODE_ANALYTICS_CLIENT_ID"},{"name":"NAMESPACE"},{"name":"PRIMARY_HOST"},{"name":"POSTGRES_USER"},{"name":"POSTGRES_PASSWORD"},{"name":"STANDBY"},{"name":"STREAMING"},{"name":"LEASE_DURATION"},{"name":"RENEW_DEADLINE"},{"name":"RETRY_PERIOD"}],"env":[{"name":"NAMESPACE","valueFrom":{"fieldRef":{"apiVersion":null}}}],"name":"postgres"}],"securityContext":null}},"volumeClaimTemplates":[{"metadata":{"annotations":{"volume.beta.kubernetes.io/storage-class":"gp2"},"creationTimestamp":null,"name":"data"},"spec":{"accessModes":["ReadWriteOnce"],"dataSource":null,"resources":{"requests":{"storage":"50Mi"}},"storageClassName":"gp2"},"status":{}}]}}.
E0406 01:03:36.955256       1 workqueue.go:51] timed out waiting for the condition
E0406 01:03:36.955273       1 worker.go:76] Failed to process key assay-definition-manager-10094388/scheduled-pg. Reason: timed out waiting for the condition
E0406 01:03:36.955303       1 worker.go:90] timed out waiting for the condition
I0406 01:03:36.955310       1 worker.go:91] Dropping key "assay-definition-manager-10094388/scheduled-pg" out of the queue: timed out waiting for the condition
E0406 01:03:37.537682       1 workqueue.go:54] timed out waiting for the condition
E0406 01:03:37.543173       1 worker.go:76] Failed to process key assay-upload-manager-10039527/scheduled-pg. Reason: timed out waiting for the condition
E0406 01:03:37.543192       1 worker.go:90] timed out waiting for the condition
I0406 01:03:37.543198       1 worker.go:91] Dropping key "assay-upload-manager-10039527/scheduled-pg" out of the queue: timed out waiting for the condition

The scheduled-pg pod logs:

The logs reported timed out waiting for the condition for any actions on it and creating scheduled snapshots. From the pod logs:

2019-04-04 17:25:38.947 UTC [261] LOG:  PID 10695 in cancel request did not match any process
2019-04-24 20:34:09.455 UTC [25734] LOG:  incomplete startup packet
2019-04-24 20:36:46.120 UTC [25746] LOG:  incomplete startup packet

and

Error from server: Get https://172.30.0.161:10250/containerLogs/assay-upload-manager-10039527/scheduled-pg-0/postgres: dial tcp 172.30.0.161:10250: connect: connection refused

kubedb-operator cluster-role

The kubedb-operator cluster-role

[issue-label-bot[bot]]

Issue-Label Bot is automatically applying the label bug to this issue, with a confidence of 0.92. Please mark this comment with :thumbsup: or :thumbsdown: to give our bot feedback!

Links: app homepage, dashboard and code for this bot.

[iamrz1]

This looks like an issue with pod security policy. An empty psp was received by database-role from an older catalog. It was an issue with kubeDB operator while upgrading from version 0.10.0 to 0.11.0. The temporary solution was then to upgrade the catalog first and then upgrading the operator. It shouldn't have been a problem in newer versions.
What version of the operator were you upgrading from?

[yazfaz]

@iamrz1 I was upgrading from 0.9.0 to 0.10.0 and we are currently on 0.10.0 (the upgrade was to get Postgres 10.2-v2, since we were on the deprecated version).

After this issue was resolved by removing KubeDB from the namespace and restoring the database from a manual backup, scheduled backups for all applications using KubeDB stopped running again. Updating the yaml file triggered them to start again.

Do you know why scheduled snapshots stopped running, both initially and after resolving the hanging pod?

[iamrz1]

It is intriguing because this seems to be an error related to missing PSP permission and PSP was only added in KubeDB version 0.11.0. So KubeDB should not have anything to do with PSP in prior versions.

Anyway, have you tried upgrading catalog version first as I mentioned before? My suggestion would be upgrading to the latest operator and catalog versions.