Postgres-operator: Database server fails to start

[aknuds1]

I'm trying to deploy Postgres Operator in a DigitalOcean cluster, but it keeps failing due to (as far as I can tell) Postgres not starting. The operator fails to create the cluster since a master is never elected (i.e. no pod gets the label spilo-role=master), and from checking the logs of the pod in question (there are two pods and the other one gets labeled as a replica), the reason appears to be that there are constant failures in trying to connect to Postgres:

2019-01-01 21:45:52,393 INFO: establishing a new patroni connection to the postgres cluster
/var/run/postgresql:5432 - accepting connections
2019-01-01 21:45:52,697 INFO: Could not take out TTL lock
2019-01-01 21:45:52,885 INFO: following new leader after trying and failing to obtain lock
2019-01-01 21:45:59,681 ERROR: get_postgresql_status
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/dist-packages/patroni/api.py", line 488, in query
    cursor.execute(sql, params)
psycopg2.OperationalError: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.


During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/dist-packages/patroni/api.py", line 437, in get_postgresql_status
    self.server.patroni.postgresql.lsn_name), retry=retry)[0]
  File "/usr/local/lib/python3.6/dist-packages/patroni/api.py", line 412, in query
    return self.server.query(sql, *params)
  File "/usr/local/lib/python3.6/dist-packages/patroni/api.py", line 493, in query
    raise PostgresConnectionException('connection problems')
patroni.exceptions.PostgresConnectionException: 'connection problems'

Can someone please help me understand why my cluster won't start? You can see my Kubernetes manifests here. You might notice I use a personal version of the operator itself, but it should behave mostly the same as the original, with some tweaks for added robustness.

Please let me know if you need more info.

[CyberDem0n]

Something wrong with labels. You can read more about labels in the Patroni documentation.

Postgres operator created discourse-production endpoint, but Patroni can't find it by using the labelSelector build from configured labels. After that Patroni wants to create the endpoint and fails because it already exists.

BTW, I didn't found postgres-operator configmap in your repo.

[CyberDem0n]

It looks like you are facing the issue similar to https://github.com/zalando-incubator/postgres-operator/issues/411

cluster_name_label: cluster-name is set in the https://github.com/aknuds1/experimental-berlin-discourse/blob/master/manifests/postgresql-operator-configuration.yaml#L25, but it is not propageted to spilo.

[aknuds1]

Thanks for the prompt response @CyberDem0n! I use the OperatorConfiguration CRD to configure the operator instead of a ConfigMap, as the former supersedes the latter does it not?

About #411, it could look as if that is indeed what I'm hitting. I will see if I can modify the operator to pass environment variables on to Spilo. Is there any reason why this isn't already fixed in the operator?

[aknuds1]

@CyberDem0n I think I fixed that issue in this PR, as I can see that the pods are able to identify themselves as respectively master and replica.

However, I still have the problem of Postgres apparently failing to start as I keep seeing these errors in the pod logs:

Master:

2019-01-02 22:38:28,345 INFO: establishing a new patroni connection to the postgres cluster
/var/run/postgresql:5432 - rejecting connections
2019-01-02 22:38:28,882 ERROR: Exception when called state_handler.last_operation()
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/dist-packages/patroni/ha.py", line 122, in update_lock
    last_operation = self.state_handler.last_operation()
  File "/usr/local/lib/python3.6/dist-packages/patroni/postgresql.py", line 1575, in last_operation
    return str(self._cluster_info_state_get('wal_position'))
  File "/usr/local/lib/python3.6/dist-packages/patroni/postgresql.py", line 749, in _cluster_info_state_get
    raise PostgresConnectionException(self._cluster_info_state['error'])
patroni.exceptions.PostgresConnectionException: "'Too many retry attempts'"
2019-01-02 22:38:28,911 INFO: Error communicating with PostgreSQL. Will try again later
2019-01-02 22:38:37,694 INFO: Lock owner: discourse-production-0; I am discourse-production-0

Replica:

2019-01-02 22:39:53,587 ERROR: get_postgresql_status
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/dist-packages/patroni/api.py", line 488, in query
    cursor.execute(sql, params)
psycopg2.OperationalError: server closed the connection unexpectedly
    This probably means the server terminated abnormally
    before or while processing the request.


During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/dist-packages/patroni/api.py", line 437, in get_postgresql_status
    self.server.patroni.postgresql.lsn_name), retry=retry)[0]
  File "/usr/local/lib/python3.6/dist-packages/patroni/api.py", line 412, in query
    return self.server.query(sql, *params)
  File "/usr/local/lib/python3.6/dist-packages/patroni/api.py", line 493, in query
    raise PostgresConnectionException('connection problems')
patroni.exceptions.PostgresConnectionException: 'connection problems'
2019-01-02 22:39:58,455 INFO: Lock owner: discourse-production-0; I am discourse-production-1

Any idea how to fix this remaining issue??

[erthalion]

Can you provide more logs? I mean, before/after this point you've posted, and Postgres logs if possible.

[aknuds1]

@erthalion Here are the complete logs for master and replica pods: gist.

[aknuds1]

@erthalion How do I get the Postgres logs though?

[aknuds1]

@erthalion I copied logs from pgdata/pgroot/pg_logs/postgresql-3.csv in the master pod: gist. Hope it helps.

[erthalion]

Can you also tell which versions of Postgres and spilo do you use? What would happen if you'll remove bg_mon from shared_libraries in Postgres configuration?

[aknuds1]

@erthalion I use Spilo image spilo-cdp-10:1.4-p29. I don't know which exact Postgres version is in use, but the operator is configured to use v10.

How do I remove bg_mon from the shared libs?

[erthalion]

I use Spilo image spilo-cdp-10:1.4-p29

Try to use latest version (spilo-cdp-11:1.5-p42) - if possible, delete the current cluster and recreate with the new spilo. To test without bg_mon, you can override shared_preload_libraries in Postgres parameters section of a manifest.

[Jan-M]

FYI: We believe you run into a problem that existed in Postgres for a few versions/commits but has be resolved by now. Thus the new Spilo image with a new Postgres version prevents Postgres from running into this error state and crash (you see all the segfaults and immediate shutdowns in your log).

Steps to try: Update your operator config to new image and recreate operator. It will try to do the rolling upgrade and this might then fix the problem. If not, delete manifest and start from scratch as I assume the cluster is still empty.

While this seems scary at first it would be resolvable as it normally does not affect the old master node or is revertable by moving the docker image forward or backwards to a working version or disabling bg_mon temporarily. (bg_mon is not the culprit, it just triggered the error).

[aknuds1]

Thanks @erthalion @Jan-M I'm gonna try, recreating the cluster if need be.

[aknuds1]

@erthalion @Jan-M from looking at the logs, it looks as if Postgres might be working now! Can't see it crashing anymore.

[Jan-M]

Happy to help, we will prep a PR updating the example manifests.