postgres-operator icon indicating copy to clipboard operation
postgres-operator copied to clipboard

Published 20 hours ago • verified publisher icon CrunchyData

psql: error: FATAL: role "hippo" does not exist with PGOv5

Open nagannv opened this issue 2 years ago • 3 comments

Created PGO V5 cluster on OpenStack Kubernetes ( 1.23), on trying to access to database instance via psql Terminal getting below errors

psql: error: FATAL:  password authentication failed for user "hippo"
FATAL:  no pg_hba.conf entry for host "127.0.0.1", user "hippo", database "hippo", no encryption 

psql: error: FATAL:  role "hippo" does not exist
E0516 11:36:49.255093 1543940 portforward.go:391] error copying from local connection to remote stream: read tcp4 127.0.0.1:5432->127.0.0.1:57362: read: connection reset by peer

Procedure:

Deployed the cluster using the eth procedure given in https://access.crunchydata.com/documentation/postgres-operator/v5/quickstart/

$ kubectl apply -k kustomize/install/namespace
namespace/postgres-operator created
$ kubectl apply --server-side -k kustomize/install/default
customresourcedefinition.apiextensions.k8s.io/pgupgrades.postgres-operator.crunchydata.com serverside-applied
customresourcedefinition.apiextensions.k8s.io/postgresclusters.postgres-operator.crunchydata.com serverside-applied
serviceaccount/pgo serverside-applied
serviceaccount/postgres-operator-upgrade serverside-applied
clusterrole.rbac.authorization.k8s.io/postgres-operator serverside-applied
clusterrole.rbac.authorization.k8s.io/postgres-operator-upgrade serverside-applied
clusterrolebinding.rbac.authorization.k8s.io/postgres-operator serverside-applied
clusterrolebinding.rbac.authorization.k8s.io/postgres-operator-upgrade serverside-applied
deployment.apps/pgo serverside-applied
deployment.apps/pgo-upgrade serverside-applied


$ kubectl get pods -n postgres-operator
NAME                          READY   STATUS    RESTARTS   AGE
pgo-5858b776c6-gnpsq          1/1     Running   0          27s
pgo-upgrade-7cf448755-jjkkw   1/1     Running   0          27s


$ kubectl apply -k kustomize/postgres
postgrescluster.postgres-operator.crunchydata.com/hippo created
$ kubectl get pods -n postgres-operator
NAME                          READY   STATUS    RESTARTS   AGE
hippo-instance1-7dhq-0        4/4     Running   0          4m24s
hippo-repo-host-0             2/2     Running   0          4m24s
pgo-5858b776c6-gnpsq          1/1     Running   0          5m14s
pgo-upgrade-7cf448755-jjkkw   1/1     Running   0          5m14s

No Job hippo-backup as shown in the below example got created

NAME                          READY   STATUS    RESTARTS   AGE
hippo-backup-t7qp--1-xm2mw     0/1     Completed   0          2m33s

$ PG_CLUSTER_PRIMARY_POD=$(kubectl get pod -n postgres-operator -o name \
>   -l postgres-operator.crunchydata.com/cluster=hippo,postgres-operator.crunchydata.com/role=master)
$ echo $PG_CLUSTER_PRIMARY_POD

Note: echo $PG_CLUSTER_PRIMARY_POD output is blank

ubuntu@somesh-form-flow:~/PGO$ kubectl -n postgres-operator port-forward hippo-instance1-7dhq-0 5432:5432&
Forwarding from 127.0.0.1:5432 -> 5432
Forwarding from [::1]:5432 -> 5432

~/PGO$ PGPASSWORD=$(kubectl get secrets -n postgres-operator "${PG_CLUSTER_USER_SECRET_NAME}" -o go-template='{{.data.password | base64decode}}') \
> PGUSER=$(kubectl get secrets -n postgres-operator "${PG_CLUSTER_USER_SECRET_NAME}" -o go-template='{{.data.user | base64decode}}') \
> PGDATABASE=$(kubectl get secrets -n postgres-operator "${PG_CLUSTER_USER_SECRET_NAME}" -o go-template='{{.data.dbname | base64decode}}') \
> psql -h localhost

Handling connection for 5432
Handling connection for 5432
psql: error: FATAL:  password authentication failed for user "hippo"
FATAL:  no pg_hba.conf entry for host "127.0.0.1", user "hippo", database "hippo", no encryption
ubuntu@somesh:~/PGO$

Appended the following lines to postgres.yaml in postgres-operator-examples-main/kustomize/postgres to see if issue can be resolved

 patroni:
    dynamicConfiguration:
      postgresql:
        pg_hba:
          - "host all all 0.0.0.0/0 trust" # this line enabled logical replication with programmatic access
          - "host all postgres 127.0.0.1/32 md5"

$ PGPASSWORD=$(kubectl get secrets -n postgres-operator "${PG_CLUSTER_USER_SECRET_NAME}" -o go-template='{{.data.password | base64decode}}') \
> PGUSER=$(kubectl get secrets -n postgres-operator "${PG_CLUSTER_USER_SECRET_NAME}" -o go-template='{{.data.user | base64decode}}') \
> PGDATABASE=$(kubectl get secrets -n postgres-operator "${PG_CLUSTER_USER_SECRET_NAME}" -o go-template='{{.data.dbname | base64decode}}') \
> psql -h localhost
Handling connection for 5432
psql: error: FATAL:  role "hippo" does not exist
E0516 11:36:49.255093 1543940 portforward.go:391] error copying from local connection to remote stream: read tcp4 127.0.0.1:5432->127.0.0.1:57362: read: connection reset by peer

/pgdata/pg14/log output


[postgres@hippo-instance1-w5wh-0 log]$ vi postgresql-Mon.log
2022-05-16 11:17:11.355 UTC [95] LOG:  starting PostgreSQL 14.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 8.5.0 20210514 (Red Hat 8.5.0-4), 64-bit
2022-05-16 11:17:11.355 UTC [95] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2022-05-16 11:17:11.355 UTC [95] LOG:  listening on IPv6 address "::", port 5432
2022-05-16 11:17:11.363 UTC [95] LOG:  listening on Unix socket "/tmp/postgres/.s.PGSQL.5432"
2022-05-16 11:17:11.373 UTC [98] LOG:  database system was shut down at 2022-05-16 11:17:11 UTC
2022-05-16 11:17:11.384 UTC [95] LOG:  database system is ready to accept connections
ERROR: [103]: unable to find a valid repository:
       repo1: [ProtocolError] expected value '2.36' for greeting key 'version' but got '2.38'
       HINT: is the same version of pgBackRest installed on the local and remote host?
2022-05-16 11:18:11.468 UTC [103] LOG:  archive command failed with exit code 103
2022-05-16 11:18:11.468 UTC [103] DETAIL:  The failed archive command was: pgbackrest --stanza=db archive-push "pg_wal/000000010000000000000001"
ERROR: [103]: unable to find a valid repository:
       repo1: [ProtocolError] expected value '2.36' for greeting key 'version' but got '2.38'
       HINT: is the same version of pgBackRest installed on the local and remote host?
2022-05-16 11:18:12.479 UTC [103] LOG:  archive command failed with exit code 103
2022-05-16 11:18:12.479 UTC [103] DETAIL:  The failed archive command was: pgbackrest --stanza=db archive-push "pg_wal/000000010000000000000001"
ERROR: [103]: unable to find a valid repository:
       repo1: [ProtocolError] expected value '2.36' for greeting key 'version' but got '2.38'
       HINT: is the same version of pgBackRest installed on the local and remote host?
2022-05-16 11:18:13.490 UTC [103] LOG:  archive command failed with exit code 103
2022-05-16 11:18:13.490 UTC [103] DETAIL:  The failed archive command was: pgbackrest --stanza=db archive-push "pg_wal/000000010000000000000001"
2022-05-16 11:18:13.490 UTC [103] WARNING:  archiving write-ahead log file "000000010000000000000001" failed too many times, will try again later
ERROR: [103]: unable to find a valid repository:
       repo1: [ProtocolError] expected value '2.36' for greeting key 'version' but got '2.38'
       HINT: is the same version of pgBackRest installed on the local and remote host?
2022-05-16 11:19:13.547 UTC [103] LOG:  archive command failed with exit code 103
2022-05-16 11:19:13.547 UTC [103] DETAIL:  The failed archive command was: pgbackrest --stanza=db archive-push "pg_wal/000000010000000000000001"
ERROR: [103]: unable to find a valid repository:
       repo1: [ProtocolError] expected value '2.36' for greeting key 'version' but got '2.38'
       HINT: is the same version of pgBackRest installed on the local and remote host?
2022-05-16 11:19:14.559 UTC [103] LOG:  archive command failed with exit code 103
2022-05-16 11:19:14.559 UTC [103] DETAIL:  The failed archive command was: pgbackrest --stanza=db archive-push "pg_wal/000000010000000000000001"
ERROR: [103]: unable to find a valid repository:
       repo1: [ProtocolError] expected value '2.36' for greeting key 'version' but got '2.38'
       HINT: is the same version of pgBackRest installed on the local and remote host?
2022-05-16 11:19:15.570 UTC [103] LOG:  archive command failed with exit code 103
2022-05-16 11:19:15.570 UTC [103] DETAIL:  The failed archive command was: pgbackrest --stanza=db archive-push "pg_wal/000000010000000000000001"
2022-05-16 11:19:15.570 UTC [103] WARNING:  archiving write-ahead log file "000000010000000000000001" failed too many times, will try again later
2022-05-16 11:19:26.488 UTC [299] FATAL:  role "hippo" does not exist
ERROR: [103]: unable to find a valid repository:
       repo1: [ProtocolError] expected value '2.36' for greeting key 'version' but got '2.38'
       HINT: is the same version of pgBackRest installed on the local and remote host?
2022-05-16 11:20:15.643 UTC [103] LOG:  archive command failed with exit code 103

nagannv avatar May 16 '22 12:05 nagannv

I have the same issue in GKE.

/pgdata/pg14/log:

bash-4.4$ more postgresql-Wed.log 
2022-05-18 04:58:28.197 UTC [109] LOG:  starting PostgreSQL 14.2 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 8.5.0 20210514 (Red Hat 8.5.0-4), 64-bit
2022-05-18 04:58:28.198 UTC [109] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2022-05-18 04:58:28.198 UTC [109] LOG:  listening on IPv6 address "::", port 5432
2022-05-18 04:58:28.204 UTC [109] LOG:  listening on Unix socket "/tmp/postgres/.s.PGSQL.5432"
2022-05-18 04:58:28.212 UTC [112] LOG:  database system was shut down at 2022-05-18 04:58:27 UTC
2022-05-18 04:58:28.222 UTC [109] LOG:  database system is ready to accept connections
ERROR: [103]: unable to find a valid repository:
       repo1: [FileMissingError] unable to load info file '/pgbackrest/repo1/archive/db/archive.info' or '/pgbackrest/repo1/archive/db/archive.info.copy':
       FileMissingError: raised from remote-0 tls protocol on 'hippo-repo-host-0.hippo-pods.postgres-operator.svc.cluster.local.': unable to open missing file '/pgbackrest/repo1/archive/db/archive.info' for read
       FileMissingError: raised from remote-0 tls protocol on 'hippo-repo-host-0.hippo-pods.postgres-operator.svc.cluster.local.': unable to open missing file '/pgbackrest/repo1/archive/db/archive.info.copy' for read
       HINT: archive.info cannot be opened but is required to push/get WAL segments.
       HINT: is archive_command configured correctly in postgresql.conf?
       HINT: has a stanza-create been performed?
       HINT: use --no-archive-check to disable archive checks during backup if you have an alternate archiving scheme.
2022-05-18 04:59:28.313 UTC [117] LOG:  archive command failed with exit code 103
2022-05-18 04:59:28.313 UTC [117] DETAIL:  The failed archive command was: pgbackrest --stanza=db archive-push "pg_wal/000000010000000000000001"
ERROR: [103]: unable to find a valid repository:
       repo1: [FileMissingError] unable to load info file '/pgbackrest/repo1/archive/db/archive.info' or '/pgbackrest/repo1/archive/db/archive.info.copy':
       FileMissingError: raised from remote-0 tls protocol on 'hippo-repo-host-0.hippo-pods.postgres-operator.svc.cluster.local.': unable to open missing file '/pgbackrest/repo1/archive/db/archive.info' for read
       FileMissingError: raised from remote-0 tls protocol on 'hippo-repo-host-0.hippo-pods.postgres-operator.svc.cluster.local.': unable to open missing file '/pgbackrest/repo1/archive/db/archive.info.copy' for read
       HINT: archive.info cannot be opened but is required to push/get WAL segments.
       HINT: is archive_command configured correctly in postgresql.conf?
       HINT: has a stanza-create been performed?
       HINT: use --no-archive-check to disable archive checks during backup if you have an alternate archiving scheme.
2022-05-18 04:59:29.335 UTC [117] LOG:  archive command failed with exit code 103
2022-05-18 04:59:29.335 UTC [117] DETAIL:  The failed archive command was: pgbackrest --stanza=db archive-push "pg_wal/000000010000000000000001"
ERROR: [103]: unable to find a valid repository:
       repo1: [FileMissingError] unable to load info file '/pgbackrest/repo1/archive/db/archive.info' or '/pgbackrest/repo1/archive/db/archive.info.copy':
       FileMissingError: raised from remote-0 tls protocol on 'hippo-repo-host-0.hippo-pods.postgres-operator.svc.cluster.local.': unable to open missing file '/pgbackrest/repo1/archive/db/archive.info' for read
       FileMissingError: raised from remote-0 tls protocol on 'hippo-repo-host-0.hippo-pods.postgres-operator.svc.cluster.local.': unable to open missing file '/pgbackrest/repo1/archive/db/archive.info.copy' for read
       HINT: archive.info cannot be opened but is required to push/get WAL segments.
       HINT: is archive_command configured correctly in postgresql.conf?
       HINT: has a stanza-create been performed?
       HINT: use --no-archive-check to disable archive checks during backup if you have an alternate archiving scheme.
2022-05-18 04:59:30.361 UTC [117] LOG:  archive command failed with exit code 103
2022-05-18 04:59:30.361 UTC [117] DETAIL:  The failed archive command was: pgbackrest --stanza=db archive-push "pg_wal/000000010000000000000001"
2022-05-18 04:59:30.361 UTC [117] WARNING:  archiving write-ahead log file "000000010000000000000001" failed too many times, will try again later
ERROR: [103]: unable to find a valid repository:
       repo1: [FileMissingError] unable to load info file '/pgbackrest/repo1/archive/db/archive.info' or '/pgbackrest/repo1/archive/db/archive.info.copy':
       FileMissingError: raised from remote-0 tls protocol on 'hippo-repo-host-0.hippo-pods.postgres-operator.svc.cluster.local.': unable to open missing file '/pgbackrest/repo1/archive/db/archive.info' for read
       FileMissingError: raised from remote-0 tls protocol on 'hippo-repo-host-0.hippo-pods.postgres-operator.svc.cluster.local.': unable to open missing file '/pgbackrest/repo1/archive/db/archive.info.copy' for read
       HINT: archive.info cannot be opened but is required to push/get WAL segments.
       HINT: is archive_command configured correctly in postgresql.conf?
       HINT: has a stanza-create been performed?
       HINT: use --no-archive-check to disable archive checks during backup if you have an alternate archiving scheme.
2022-05-18 05:00:30.445 UTC [117] LOG:  archive command failed with exit code 103
2022-05-18 05:00:30.445 UTC [117] DETAIL:  The failed archive command was: pgbackrest --stanza=db archive-push "pg_wal/000000010000000000000001"
ERROR: [103]: unable to find a valid repository:
       repo1: [FileMissingError] unable to load info file '/pgbackrest/repo1/archive/db/archive.info' or '/pgbackrest/repo1/archive/db/archive.info.copy':
       FileMissingError: raised from remote-0 tls protocol on 'hippo-repo-host-0.hippo-pods.postgres-operator.svc.cluster.local.': unable to open missing file '/pgbackrest/repo1/archive/db/archive.info' for read
       FileMissingError: raised from remote-0 tls protocol on 'hippo-repo-host-0.hippo-pods.postgres-operator.svc.cluster.local.': unable to open missing file '/pgbackrest/repo1/archive/db/archive.info.copy' for read
       HINT: archive.info cannot be opened but is required to push/get WAL segments.
       HINT: is archive_command configured correctly in postgresql.conf?

<snip>

If I login as postgres (I modified pg_hba.conf to allow this), I can see that the database is up and running but the hippo user and database are not created:

postgres=# \du
                                     List of roles
  Role name   |                         Attributes                         | Member of 
--------------+------------------------------------------------------------+-----------
 _crunchyrepl | Replication                                                | {}
 postgres     | Superuser, Create role, Create DB, Replication, Bypass RLS | {}

postgres=# \l
                                  List of databases
   Name    |  Owner   | Encoding |   Collate   |    Ctype    |   Access privileges   
-----------+----------+----------+-------------+-------------+-----------------------
 postgres  | postgres | UTF8     | en_US.utf-8 | en_US.utf-8 | 
 template0 | postgres | UTF8     | en_US.utf-8 | en_US.utf-8 | =c/postgres          +
           |          |          |             |             | postgres=CTc/postgres
 template1 | postgres | UTF8     | en_US.utf-8 | en_US.utf-8 | =c/postgres          +
           |          |          |             |             | postgres=CTc/postgres
(3 rows)

vhadianto avatar May 18 '22 05:05 vhadianto

For anyone following, i had the same results as this but discovered the issue was in the use of apostrophes with usernames:

users:
- name: 'user'
  databases:
    - example

Removing the apostrophes worked

B1ue-W01f avatar Jun 23 '22 14:06 B1ue-W01f

@nagannv or @vhadianto can you provide a copy of your PostgresCluster spec? I am specifically curious if there is an issue with PGO attempting to create the users specified in the spec, e.g. similar to the issue and fix described byt @B1ue-W01f in the previous comment.

The PostgresCluster status should also provide insight into other aspects of the cluster initialization process, e.g. to see if any other unexpected behavior might be occurring during cluster initialization.

andrewlecuyer avatar Jul 13 '22 04:07 andrewlecuyer