Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Bug]: New replica searches for WAL archive that doesn't exist #4412

Open
4 tasks done
stevec-skyhawk opened this issue Apr 30, 2024 · 2 comments
Open
4 tasks done

[Bug]: New replica searches for WAL archive that doesn't exist #4412

stevec-skyhawk opened this issue Apr 30, 2024 · 2 comments
Assignees
@gbartolini
Labels
triage Pending triage

Comments

@stevec-skyhawk
Copy link

stevec-skyhawk commented Apr 30, 2024 •
edited

Is there an existing issue already for this bug?

  • I have searched for an existing issue, and could not find anything. I believe this is a new bug.

I have read the troubleshooting guide

  • I have read the troubleshooting guide and I think this is a new bug.

I am running a supported version of CloudNativePG

  • I have read the troubleshooting guide and I think this is a new bug.

Contact Details

stephen.corcoran@telus.com

Version

1.23.0

What version of Kubernetes are you using?

1.29

What is your Kubernetes environment?

Cloud: Amazon EKS

How did you install the operator?

YAML manifest

What happened?

  • Cluster experienced an issue and failed over (Node resources issue)
  • Original primary does not come back online. End up destroying it
  • Make a volume snapshot before starting new replica so the recovery doesn't have to go through large WAL archive
  • When attempting to spin up a new replica the logs suggest the new replica is looking for a WAL archive that doesn't exist.

Status of cluster at time the new replica is requested (scaling up)
First Point of Recoverability: 2024-04-30T14:01:25Z
Working WAL archiving: OK
WALs waiting to be archived: 0
Last Archived WAL: 0000001100000682000000E2 @ 2024-04-30T20:36:13.111958Z
Last Failed WAL: 00000011.history @ 2024-04-30T18:52:16.746355Z

When the replica pod starts up, the logs suggest its looking for a file that doesn't exist yet:
"logger":"wal-restore","msg":"WAL file not found in the recovery object store","logging_pod":"pgv2-dev-11","walName":"00000012.history"

I can also verify that the wal archive does not exist in the pg_wal directory on the primary so it wasn't a flushing issue.

The cnpg status will indicate the replica is in Standby (file based) recovery, but it does not fully synchronize.

Instances status
Name Database Size Current LSN Replication role Status QoS Manager Version

pgv2-dev-1 719 GB 682/E3002900 Primary OK Guaranteed 1.23.0
pgv2-dev-11 719 GB 682/E40000A0 Standby (file based) OK Guaranteed 1.23.0
pgv2-dev-3 719 GB 682/E3002900 Standby (sync) OK Guaranteed 1.23.0

Cluster resource

apiVersion: postgresql.cnpg.io/v1
kind: Cluster
metadata:
  name: pgv2-dev
  namespace: pgdb
spec:
  description: V2 Database Cluster DEV
  imageName: ghcr.io/cloudnative-pg/postgis:16-3.4

  instances: 2
  maxSyncReplicas: 1
  minSyncReplicas: 1

  logLevel: debug
  enableSuperuserAccess: true
  enablePDB: true
  superuserSecret:
    name: superuser-auth
  smartShutdownTimeout: 180
  startDelay: 300
  stopDelay: 300
  failoverDelay: 0
  switchoverDelay: 300


  primaryUpdateMethod: restart
  primaryUpdateStrategy: unsupervised

  serviceAccountTemplate:
    metadata:
      annotations:
        eks.amazonaws.com/role-arn: <AWS ARN>
  bootstrap:
    recovery:
      source: v2
      database: v2dev
      owner: app
      secret:
        name: app-auth
      volumeSnapshots:
        #Make a volume snapshot backup JUST BEFORE creating this cluster
        storage:
          apiGroup: snapshot.storage.k8s.io
          kind: VolumeSnapshot
          name: v2-yyyyMMddhhmmss
        walStorage:
          apiGroup: snapshot.storage.k8s.io
          kind: VolumeSnapshot
          name: v2-yyyyMMddhhmmss-wal

  externalClusters:
  - name: v2
    barmanObjectStore:
      data:
        compression: gzip
        jobs: 2
      destinationPath: s3://<BUCKET DIR>
      s3Credentials:
        inheritFromIAMRole: true
      wal:
        compression: gzip
        maxParallel: 20
    connectionParameters:
      dbname: postgres
      host: v2-rw.default.svc
      user: postgres
    password:
      key: password
      name: superuser-auth

  replica:
    enabled: true
    source: v2

  replicationSlots:
    highAvailability:
      enabled: true
      slotPrefix: _cnpg_
    synchronizeReplicas:
      enabled: true
    updateInterval: 300

  postgresql:
    parameters:
      archive_mode: "on"
      archive_timeout: 5min
      auto_explain.log_min_duration: 10s
      dynamic_shared_memory_type: posix
      log_destination: csvlog
      log_directory: /controller/log
      log_filename: postgres
      log_rotation_age: "0"
      log_rotation_size: "0"
      log_truncate_on_rotation: "false"
      logging_collector: "on"
      maintenance_work_mem: 1GB
      max_connections: "600"
      max_parallel_workers: "32"
      max_parallel_workers_per_gather: "4"
      max_replication_slots: "32"
      max_wal_size: 2048MB
      max_worker_processes: "32"
      pg_stat_statements.max: "10000"
      pg_stat_statements.track: all
      shared_buffers: 1GB
      shared_memory_type: mmap
      shared_preload_libraries: ""
      ssl_max_protocol_version: TLSv1.3
      ssl_min_protocol_version: TLSv1.3
      wal_keep_size: 1024MB
      wal_level: logical
      wal_log_hints: "on"
      wal_receiver_timeout: 10s
      wal_sender_timeout: 10s
      work_mem: 256MB
    pg_hba:
    - host all app all password
    syncReplicaElectionConstraint:
      enabled: false

  backup:
    barmanObjectStore:
      data:
        compression: gzip
        jobs: 2
      destinationPath: s3://<BUCKET DIR>/
      s3Credentials:
        inheritFromIAMRole: true
      wal:
        compression: gzip
        maxParallel: 20
    retentionPolicy: 30d
    target: prefer-standby
    volumeSnapshot:
      className: v2-vsc
      online: true
      onlineConfiguration:
        immediateCheckpoint: true
        waitForArchive: false
      snapshotOwnerReference: none
      walClassName: v2-vsc-wal

  monitoring:
    customQueriesConfigMap:
    - key: queries
      name: cnpg-default-monitoring
    disableDefaultQueries: false
    enablePodMonitor: false
  resources:
    limits:
      cpu: "3"
      memory: 4Gi
    requests:
      cpu: "3"
      memory: 4Gi
  storage:
    resizeInUseVolumes: true
    size: 3000Gi
    storageClass: gp3
  walStorage:
    resizeInUseVolumes: true
    size: 50Gi
    storageClass: io2-unencrypted
  affinity:
    enablePodAntiAffinity: true
    nodeAffinity:
      requiredDuringSchedulingIgnoredDuringExecution:
        nodeSelectorTerms:
        - matchExpressions:
          - key: eks.amazonaws.com/nodegroup
            operator: In
            values:
            - pgdb-server
    podAntiAffinityType: preferred
    topologyKey: failure-domain.beta.kubernetes.io/zone

Relevant log output

stream logs failed container "postgres" in pod "pgv2-dev-11" is waiting to start: PodInitializing for pgdb/pgv2-dev-11 (postgres)
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"setup","msg":"Starting CloudNativePG Instance Manager","logging_pod":"pgv2-dev-11","version":"1.23.0","build":{"Version":"1.23.0","Commit":"f6292625","Date":"2024-04-25"}}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"setup","msg":"starting tablespace manager","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"setup","msg":"starting external server manager","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"setup","msg":"starting controller-runtime manager","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting EventSource","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","source":"kind source: *v1.Cluster"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting Controller","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting webserver","logging_pod":"pgv2-dev-11","address":":9187"}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"roles_reconciler","msg":"starting up the runnable","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:25Z","msg":"starting the postgres loop","caller":"internal/cmd/manager/instance/run/lifecycle/lifecycle.go:74","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:25Z","msg":"starting signal loop","caller":"internal/cmd/manager/instance/run/lifecycle/lifecycle.go:81","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"roles_reconciler","msg":"setting up RoleSynchronizer loop","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:25Z","msg":"Checking PGDATA coherence","caller":"pkg/management/postgres/instance.go:296","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting webserver","logging_pod":"pgv2-dev-11","address":"localhost:8010"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting webserver","logging_pod":"pgv2-dev-11","address":":8000"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting EventSource","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","source":"kind source: *v1.Cluster"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting Controller","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting EventSource","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","source":"kind source: *v1.Cluster"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting Controller","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting workers","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","worker count":1}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting workers","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","worker count":1}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting workers","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","worker count":1}
{"level":"debug","ts":"2024-04-30T20:40:25Z","logger":"tbs_reconciler","msg":"no tablespaces to create","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"98b7c93f-91d2-4d99-9245-72823280b28b","caller":"internal/management/controller/tablespaces/reconciler.go:68","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:25Z","msg":"Reconciling Cluster","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","caller":"internal/management/controller/instance_controller.go:111","logging_pod":"pgv2-dev-11","cluster":{"apiVersion":"postgresql.cnpg.io/v1","kind":"Cluster","namespace":"pgdb","name":"pgv2-dev"}}
{"level":"debug","ts":"2024-04-30T20:40:25Z","logger":"external_servers_reconciler","msg":"starting up the external servers reconciler","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"6f865827-ab7c-4a90-b4b6-321a879e262a","caller":"internal/management/controller/externalservers/reconciler.go:56","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:25Z","msg":"Reconciling custom monitoring queries","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","caller":"internal/management/controller/instance_controller.go:753","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:25Z","msg":"External server connection string","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"6f865827-ab7c-4a90-b4b6-321a879e262a","serverName":"v2","caller":"internal/management/controller/externalservers/reconciler.go:80","logging_pod":"pgv2-dev-11","connectionString":"dbname='postgres' host='v2-rw.default.svc' passfile='/controller/external/v2/pgpass' user='postgres'"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Refreshed configuration file","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11","filename":"/controller/certificates/server.crt","secret":"pgv2-dev-server"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Refreshed configuration file","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11","filename":"/controller/certificates/server.key","secret":"pgv2-dev-server"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Refreshed configuration file","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11","filename":"/controller/certificates/streaming_replica.crt","secret":"pgv2-dev-replication"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Refreshed configuration file","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11","filename":"/controller/certificates/streaming_replica.key","secret":"pgv2-dev-replication"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Refreshed configuration file","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11","filename":"/controller/certificates/client-ca.crt","secret":"pgv2-dev-ca"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Refreshed configuration file","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11","filename":"/controller/certificates/server-ca.crt","secret":"pgv2-dev-ca"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Installed configuration file","logging_pod":"pgv2-dev-11","pgdata":"/var/lib/postgresql/data/pgdata","filename":"pg_ident.conf"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Cluster status","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11","currentPrimary":"pgv2-dev-1","targetPrimary":"pgv2-dev-1","isReplicaCluster":false}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"This is an old primary instance, waiting for the switchover to finish","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11","currentPrimary":"pgv2-dev-1","targetPrimary":"pgv2-dev-1"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Switchover completed","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11","targetPrimary":"pgv2-dev-1","currentPrimary":"pgv2-dev-1"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Waiting for the new primary to be available","logging_pod":"pgv2-dev-11","primaryConnInfo":"host=pgv2-dev-rw user=streaming_replica port=5432 sslkey=/controller/certificates/streaming_replica.key sslcert=/controller/certificates/streaming_replica.crt sslrootcert=/controller/certificates/server-ca.crt application_name=pgv2-dev-11 sslmode=verify-ca dbname=postgres connect_timeout=5"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Extracting pg_controldata information","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11","reason":"before pg_rewind"}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"pg_controldata","msg":"pg_control version number:            1300\nCatalog version number:               202307071\nDatabase system identifier:           7345552334997741588\nDatabase cluster state:               in archive recovery\npg_control last modified:             Tue 30 Apr 2024 08:37:38 PM UTC\nLatest checkpoint location:           682/E251A0C8\nLatest checkpoint's REDO location:    682/E251A040\nLatest checkpoint's REDO WAL file:    0000001100000682000000E2\nLatest checkpoint's TimeLineID:       17\nLatest checkpoint's PrevTimeLineID:   17\nLatest checkpoint's full_page_writes: on\nLatest checkpoint's NextXID:          0:181815604\nLatest checkpoint's NextOID:          149694561\nLatest checkpoint's NextMultiXactId:  1\nLatest checkpoint's NextMultiOffset:  0\nLatest checkpoint's oldestXID:        722\nLatest checkpoint's oldestXID's DB:   1\nLatest checkpoint's oldestActiveXID:  181815603\nLatest checkpoint's oldestMultiXid:   1\nLatest checkpoint's oldestMulti's DB: 1\nLatest checkpoint's oldestCommitTsXid:0\nLatest checkpoint's newestCommitTsXid:0\nTime of latest checkpoint:            Tue 30 Apr 2024 08:35:11 PM UTC\nFake LSN counter for unlogged rels:   0/3E8\nMinimum recovery ending location:     682/E3000000\nMin recovery ending loc's timeline:   17\nBackup start location:                0/0\nBackup end location:                  0/0\nEnd-of-backup record required:        no\nwal_level setting:                    logical\nwal_log_hints setting:                on\nmax_connections setting:              600\nmax_worker_processes setting:         32\nmax_wal_senders setting:              10\nmax_prepared_xacts setting:           0\nmax_locks_per_xact setting:           64\ntrack_commit_timestamp setting:       off\nMaximum data alignment:               8\nDatabase block size:                  8192\nBlocks per segment of large relation: 131072\nWAL block size:                       8192\nBytes per WAL segment:                16777216\nMaximum length of identifiers:        64\nMaximum columns in an index:          32\nMaximum size of a TOAST chunk:        1996\nSize of a large-object chunk:         2048\nDate/time type storage:               64-bit integers\nFloat8 argument passing:              by value\nData page checksum version:           0\nMock authentication nonce:            b2ae8cbe39949b76539a9f04f6903695bba7311148df10284169aa832cc898ae\n","pipe":"stdout","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","msg":"Starting up pg_rewind","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11","pgdata":"/var/lib/postgresql/data/pgdata","options":["-P","--source-server","host=pgv2-dev-rw user=streaming_replica port=5432 sslkey=/controller/certificates/streaming_replica.key sslcert=/controller/certificates/streaming_replica.crt sslrootcert=/controller/certificates/server-ca.crt application_name=pgv2-dev-11 sslmode=verify-ca dbname=postgres","--target-pgdata","/var/lib/postgresql/data/pgdata","--restore-target-wal"]}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"pg_rewind","msg":"pg_rewind: connected to server","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"pg_rewind","msg":"pg_rewind: executing \"/usr/lib/postgresql/16/bin/postgres\" for target server to complete crash recovery","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"pg_rewind","msg":"2024-04-30 20:40:25.801 UTC [29] LOG:  database system was interrupted while in recovery at log time 2024-04-30 20:35:11 UTC","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"pg_rewind","msg":"2024-04-30 20:40:25.801 UTC [29] HINT:  If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"pg_rewind","msg":"2024-04-30 20:40:25.905 UTC [29] LOG:  database system was not properly shut down; automatic recovery in progress","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"pg_rewind","msg":"2024-04-30 20:40:25.969 UTC [29] LOG:  redo starts at 682/E251A040","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"pg_rewind","msg":"2024-04-30 20:40:25.999 UTC [29] LOG:  unexpected pageaddr 680/60000000 in WAL segment 0000001100000682000000E3, LSN 682/E3000000, offset 0","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:25Z","logger":"pg_rewind","msg":"2024-04-30 20:40:25.999 UTC [29] LOG:  redo done at 682/E251A1C8 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.03 s","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:26Z","logger":"external_servers_reconciler","msg":"starting up the external servers reconciler","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"0d35dfe0-84ee-4a1e-bbe0-0debe5696f32","caller":"internal/management/controller/externalservers/reconciler.go:56","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:26Z","logger":"tbs_reconciler","msg":"no tablespaces to create","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"37020710-021e-430c-b564-eae2cb5f6b96","caller":"internal/management/controller/tablespaces/reconciler.go:68","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:26Z","msg":"External server connection string","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"0d35dfe0-84ee-4a1e-bbe0-0debe5696f32","serverName":"v2","caller":"internal/management/controller/externalservers/reconciler.go:80","logging_pod":"pgv2-dev-11","connectionString":"dbname='postgres' host='v2-rw.default.svc' passfile='/controller/external/v2/pgpass' user='postgres'"}
{"level":"debug","ts":"2024-04-30T20:40:26Z","logger":"tbs_reconciler","msg":"no tablespaces to create","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"c507c153-4fa1-4523-933d-9de54f7b372f","caller":"internal/management/controller/tablespaces/reconciler.go:68","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:26Z","logger":"external_servers_reconciler","msg":"starting up the external servers reconciler","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"70c90437-ecc1-4b01-8ff7-11f78af99451","caller":"internal/management/controller/externalservers/reconciler.go:56","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:26Z","msg":"External server connection string","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"70c90437-ecc1-4b01-8ff7-11f78af99451","serverName":"v2","caller":"internal/management/controller/externalservers/reconciler.go:80","logging_pod":"pgv2-dev-11","connectionString":"dbname='postgres' host='v2-rw.default.svc' passfile='/controller/external/v2/pgpass' user='postgres'"}
{"level":"info","ts":"2024-04-30T20:40:26Z","logger":"pg_rewind","msg":"2024-04-30 20:40:26.221 UTC [29] LOG:  checkpoint starting: end-of-recovery immediate wait","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:26Z","logger":"pg_rewind","msg":"2024-04-30 20:40:26.223 UTC [29] LOG:  checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s; distance=11159 kB, estimate=11159 kB; lsn=682/E3000028, redo lsn=682/E3000028","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"pg_rewind","msg":"PostgreSQL stand-alone backend 16.2 (Debian 16.2-1.pgdg110+2)","pipe":"stdout","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"pg_rewind","msg":"2024-04-30 20:40:27.103 UTC [29] LOG:  checkpoint starting: shutdown immediate","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"pg_rewind","msg":"2024-04-30 20:40:27.123 UTC [29] LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 WAL file(s) added, 1 removed, 0 recycled; write=0.002 s, sync=0.001 s, total=0.020 s; sync files=0, longest=0.000 s, average=0.000 s; distance=16384 kB, estimate=16384 kB; lsn=682/E4000028, redo lsn=682/E4000028","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"pg_rewind","msg":"pg_rewind: source and target cluster are on the same timeline","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"pg_rewind","msg":"pg_rewind: no rewind required","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"pg_rewind","msg":"backend> ","pipe":"stdout","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","msg":"Demoting instance","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11","pgpdata":"/var/lib/postgresql/data/pgdata"}
{"level":"info","ts":"2024-04-30T20:40:27Z","msg":"Updated replication settings","logging_pod":"pgv2-dev-11","filename":"override.conf"}
{"level":"info","ts":"2024-04-30T20:40:27Z","msg":"Extracting pg_controldata information","logging_pod":"pgv2-dev-11","reason":"postmaster start up"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"pg_controldata","msg":"pg_control version number:            1300\nCatalog version number:               202307071\nDatabase system identifier:           7345552334997741588\nDatabase cluster state:               shut down\npg_control last modified:             Tue 30 Apr 2024 08:40:27 PM UTC\nLatest checkpoint location:           682/E4000028\nLatest checkpoint's REDO location:    682/E4000028\nLatest checkpoint's REDO WAL file:    0000001100000682000000E4\nLatest checkpoint's TimeLineID:       17\nLatest checkpoint's PrevTimeLineID:   17\nLatest checkpoint's full_page_writes: on\nLatest checkpoint's NextXID:          0:181815604\nLatest checkpoint's NextOID:          149694561\nLatest checkpoint's NextMultiXactId:  1\nLatest checkpoint's NextMultiOffset:  0\nLatest checkpoint's oldestXID:        722\nLatest checkpoint's oldestXID's DB:   1\nLatest checkpoint's oldestActiveXID:  0\nLatest checkpoint's oldestMultiXid:   1\nLatest checkpoint's oldestMulti's DB: 1\nLatest checkpoint's oldestCommitTsXid:0\nLatest checkpoint's newestCommitTsXid:0\nTime of latest checkpoint:            Tue 30 Apr 2024 08:40:27 PM UTC\nFake LSN counter for unlogged rels:   0/3E8\nMinimum recovery ending location:     0/0\nMin recovery ending loc's timeline:   0\nBackup start location:                0/0\nBackup end location:                  0/0\nEnd-of-backup record required:        no\nwal_level setting:                    logical\nwal_log_hints setting:                on\nmax_connections setting:              600\nmax_worker_processes setting:         32\nmax_wal_senders setting:              10\nmax_prepared_xacts setting:           0\nmax_locks_per_xact setting:           64\ntrack_commit_timestamp setting:       off\nMaximum data alignment:               8\nDatabase block size:                  8192\nBlocks per segment of large relation: 131072\nWAL block size:                       8192\nBytes per WAL segment:                16777216\nMaximum length of identifiers:        64\nMaximum columns in an index:          32\nMaximum size of a TOAST chunk:        1996\nSize of a large-object chunk:         2048\nDate/time type storage:               64-bit integers\nFloat8 argument passing:              by value\nData page checksum version:           0\nMock authentication nonce:            b2ae8cbe39949b76539a9f04f6903695bba7311148df10284169aa832cc898ae\n","pipe":"stdout","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","msg":"Instance is still down, will retry in 1 second","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"15648365-92da-4ecc-8e11-968e7875036a","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:27Z","msg":"Reconciling Cluster","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"320fac48-6f15-4133-940f-8df5cc0f128d","caller":"internal/management/controller/instance_controller.go:111","logging_pod":"pgv2-dev-11","cluster":{"apiVersion":"postgresql.cnpg.io/v1","kind":"Cluster","namespace":"pgdb","name":"pgv2-dev"}}
{"level":"debug","ts":"2024-04-30T20:40:27Z","msg":"Reconciling custom monitoring queries","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"320fac48-6f15-4133-940f-8df5cc0f128d","caller":"internal/management/controller/instance_controller.go:753","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"2024-04-30 20:40:27.180 UTC [32] LOG:  redirecting log output to logging collector process","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"2024-04-30 20:40:27.180 UTC [32] HINT:  Future log output will appear in directory \"/controller/log\".","pipe":"stderr","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:27.180 UTC","process_id":"32","session_id":"6631573b.20","session_line_num":"1","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"ending log output to stderr","hint":"Future log output will go to log destination \"csvlog\".","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:27.180 UTC","process_id":"32","session_id":"6631573b.20","session_line_num":"2","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"starting PostgreSQL 16.2 (Debian 16.2-1.pgdg110+2) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:27.180 UTC","process_id":"32","session_id":"6631573b.20","session_line_num":"3","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"listening on IPv4 address \"0.0.0.0\", port 5432","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:27.180 UTC","process_id":"32","session_id":"6631573b.20","session_line_num":"4","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"listening on IPv6 address \"::\", port 5432","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"2024-04-30 20:40:27.180 UTC [32] LOG:  ending log output to stderr","source":"/controller/log/postgres","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"2024-04-30 20:40:27.180 UTC [32] HINT:  Future log output will go to log destination \"csvlog\".","source":"/controller/log/postgres","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:27.183 UTC","process_id":"32","session_id":"6631573b.20","session_line_num":"5","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"listening on Unix socket \"/controller/run/.s.PGSQL.5432\"","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:27.188 UTC","process_id":"36","session_id":"6631573b.24","session_line_num":"1","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"database system was shut down at 2024-04-30 20:40:27 UTC","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:27Z","msg":"Updated replication settings","logging_pod":"pgv2-dev-11","filename":"override.conf"}
{"level":"debug","ts":"2024-04-30T20:40:27Z","msg":"Cached object request received","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","msg":"Updated replication settings","logging_pod":"pgv2-dev-11","filename":"override.conf"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:27.290 UTC","user_name":"postgres","database_name":"postgres","process_id":"46","connection_from":"[local]","session_id":"6631573b.2e","session_line_num":"1","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:27Z","msg":"Cached object request received","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:27Z","msg":"DB not available, will retry","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"320fac48-6f15-4133-940f-8df5cc0f128d","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:27.292 UTC","user_name":"postgres","database_name":"postgres","process_id":"47","connection_from":"[local]","session_id":"6631573b.2f","session_line_num":"1","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"wal-restore","msg":"WAL file not found in the recovery object store","logging_pod":"pgv2-dev-11","walName":"00000012.history","options":["--cloud-provider","aws-s3","s3://x319-cnpg-barman-bucket/","pgv2-dev"],"startTime":"2024-04-30T20:40:27Z","endTime":"2024-04-30T20:40:27Z","elapsedWalTime":0.362220191}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:27.757 UTC","process_id":"36","session_id":"6631573b.24","session_line_num":"2","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"entering standby mode","backend_type":"startup","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:27Z","msg":"Cached object request received","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:27Z","msg":"Instance status probe failing","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:27.781 UTC","user_name":"postgres","database_name":"postgres","process_id":"57","connection_from":"[local]","session_id":"6631573b.39","session_line_num":"1","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:27Z","msg":"Cached object request received","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:27Z","msg":"Instance status probe failing","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:27.872 UTC","user_name":"postgres","database_name":"postgres","process_id":"59","connection_from":"[local]","session_id":"6631573b.3b","session_line_num":"1","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:27Z","msg":"Instance status probe failing","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"info","ts":"2024-04-30T20:40:27Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:27.927 UTC","user_name":"postgres","database_name":"postgres","process_id":"60","connection_from":"[local]","session_id":"6631573b.3c","session_line_num":"1","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:28Z","msg":"Reconciling Cluster","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"2bdb660e-46b5-4c6a-a18e-bc17bdffd380","caller":"internal/management/controller/instance_controller.go:111","logging_pod":"pgv2-dev-11","cluster":{"apiVersion":"postgresql.cnpg.io/v1","kind":"Cluster","namespace":"pgdb","name":"pgv2-dev"}}
{"level":"debug","ts":"2024-04-30T20:40:28Z","msg":"Reconciling custom monitoring queries","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"2bdb660e-46b5-4c6a-a18e-bc17bdffd380","caller":"internal/management/controller/instance_controller.go:753","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:28Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:28.190 UTC","user_name":"postgres","database_name":"postgres","process_id":"62","connection_from":"[local]","session_id":"6631573c.3e","session_line_num":"1","session_start_time":"2024-04-30 20:40:28 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:28Z","msg":"Instance status probe failing","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"info","ts":"2024-04-30T20:40:28Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:28.212 UTC","user_name":"postgres","database_name":"postgres","process_id":"63","connection_from":"[local]","session_id":"6631573c.3f","session_line_num":"1","session_start_time":"2024-04-30 20:40:28 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:28Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:28.214 UTC","user_name":"postgres","database_name":"postgres","process_id":"64","connection_from":"[local]","session_id":"6631573c.40","session_line_num":"1","session_start_time":"2024-04-30 20:40:28 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:28Z","msg":"DB not available, will retry","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"2bdb660e-46b5-4c6a-a18e-bc17bdffd380","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"info","ts":"2024-04-30T20:40:28Z","logger":"wal-restore","msg":"Restored WAL file","logging_pod":"pgv2-dev-11","walName":"00000011.history","startTime":"2024-04-30T20:40:27Z","endTime":"2024-04-30T20:40:28Z","elapsedWalTime":0.3778327}
{"level":"info","ts":"2024-04-30T20:40:28Z","logger":"wal-restore","msg":"WAL restore command completed (parallel)","logging_pod":"pgv2-dev-11","walName":"00000011.history","maxParallel":20,"successfulWalRestore":1,"failedWalRestore":19,"endOfWALStream":false,"startTime":"2024-04-30T20:40:27Z","downloadStartTime":"2024-04-30T20:40:27Z","downloadTotalTime":0.378065225,"totalTime":0.456196816}
{"level":"info","ts":"2024-04-30T20:40:28Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:28.237 UTC","process_id":"36","session_id":"6631573b.24","session_line_num":"3","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"restored log file \"00000011.history\" from archive","backend_type":"startup","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:28Z","msg":"Cached object request received","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:28Z","msg":"Cached object request received","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:29Z","msg":"Reconciling Cluster","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"0dccee4c-a55c-4ce4-9eab-b69d2bf40ce9","caller":"internal/management/controller/instance_controller.go:111","logging_pod":"pgv2-dev-11","cluster":{"apiVersion":"postgresql.cnpg.io/v1","kind":"Cluster","namespace":"pgdb","name":"pgv2-dev"}}
{"level":"debug","ts":"2024-04-30T20:40:29Z","msg":"Reconciling custom monitoring queries","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"0dccee4c-a55c-4ce4-9eab-b69d2bf40ce9","caller":"internal/management/controller/instance_controller.go:753","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:29Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:29.512 UTC","user_name":"postgres","database_name":"postgres","process_id":"111","connection_from":"[local]","session_id":"6631573d.6f","session_line_num":"1","session_start_time":"2024-04-30 20:40:29 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:29Z","msg":"Instance status probe failing","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"info","ts":"2024-04-30T20:40:29Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:29.532 UTC","user_name":"postgres","database_name":"postgres","process_id":"112","connection_from":"[local]","session_id":"6631573d.70","session_line_num":"1","session_start_time":"2024-04-30 20:40:29 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:29Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:29.588 UTC","user_name":"postgres","database_name":"postgres","process_id":"113","connection_from":"[local]","session_id":"6631573d.71","session_line_num":"1","session_start_time":"2024-04-30 20:40:29 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:29Z","msg":"DB not available, will retry","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"0dccee4c-a55c-4ce4-9eab-b69d2bf40ce9","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"debug","ts":"2024-04-30T20:40:30Z","msg":"Reconciling Cluster","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"598035a4-2e04-44b5-83a7-7514d47b62f6","caller":"internal/management/controller/instance_controller.go:111","logging_pod":"pgv2-dev-11","cluster":{"apiVersion":"postgresql.cnpg.io/v1","kind":"Cluster","namespace":"pgdb","name":"pgv2-dev"}}
{"level":"debug","ts":"2024-04-30T20:40:30Z","msg":"Reconciling custom monitoring queries","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"598035a4-2e04-44b5-83a7-7514d47b62f6","caller":"internal/management/controller/instance_controller.go:753","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:30Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:30.708 UTC","user_name":"postgres","database_name":"postgres","process_id":"115","connection_from":"[local]","session_id":"6631573e.73","session_line_num":"1","session_start_time":"2024-04-30 20:40:30 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:30Z","msg":"Instance status probe failing","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"info","ts":"2024-04-30T20:40:30Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:30.740 UTC","user_name":"postgres","database_name":"postgres","process_id":"116","connection_from":"[local]","session_id":"6631573e.74","session_line_num":"1","session_start_time":"2024-04-30 20:40:30 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:30Z","msg":"Instance status probe failing","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"info","ts":"2024-04-30T20:40:30Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:30.809 UTC","user_name":"postgres","database_name":"postgres","process_id":"117","connection_from":"[local]","session_id":"6631573e.75","session_line_num":"1","session_start_time":"2024-04-30 20:40:30 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:30Z","msg":"Instance status probe failing","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"info","ts":"2024-04-30T20:40:31Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:31.014 UTC","user_name":"postgres","database_name":"postgres","process_id":"118","connection_from":"[local]","session_id":"6631573f.76","session_line_num":"1","session_start_time":"2024-04-30 20:40:31 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:31Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:31.032 UTC","user_name":"postgres","database_name":"postgres","process_id":"119","connection_from":"[local]","session_id":"6631573f.77","session_line_num":"1","session_start_time":"2024-04-30 20:40:31 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:31Z","msg":"DB not available, will retry","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"598035a4-2e04-44b5-83a7-7514d47b62f6","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"info","ts":"2024-04-30T20:40:31Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:31.124 UTC","user_name":"postgres","database_name":"postgres","process_id":"120","connection_from":"[local]","session_id":"6631573f.78","session_line_num":"1","session_start_time":"2024-04-30 20:40:31 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"57P03","message":"the database system is starting up","backend_type":"client backend","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:31Z","msg":"Instance status probe failing","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11","err":"failed to connect to `host=/controller/run user=postgres database=postgres`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))"}
{"level":"info","ts":"2024-04-30T20:40:31Z","logger":"wal-restore","msg":"WAL file not found in the recovery object store","logging_pod":"pgv2-dev-11","walName":"0000001100000682000000E4","options":["--cloud-provider","aws-s3","s3://x319-cnpg-barman-bucket/","pgv2-dev"],"startTime":"2024-04-30T20:40:28Z","endTime":"2024-04-30T20:40:31Z","elapsedWalTime":3.152753172}
{"level":"info","ts":"2024-04-30T20:40:31Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:31.604 UTC","process_id":"36","session_id":"6631573b.24","session_line_num":"4","session_start_time":"2024-04-30 20:40:27 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"consistent recovery state reached at 682/E40000A0","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:31Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:31.604 UTC","process_id":"36","session_id":"6631573b.24","session_line_num":"5","session_start_time":"2024-04-30 20:40:27 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"invalid record length at 682/E40000A0: expected at least 24, got 0","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:31Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:31.604 UTC","process_id":"32","session_id":"6631573b.20","session_line_num":"6","session_start_time":"2024-04-30 20:40:27 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"database system is ready to accept read-only connections","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:31Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:31.614 UTC","process_id":"121","session_id":"6631573f.79","session_line_num":"1","session_start_time":"2024-04-30 20:40:31 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"started streaming WAL from primary at 682/E4000000 on timeline 17","backend_type":"walreceiver","query_id":"0"}}
{"level":"info","ts":"2024-04-30T20:40:31Z","logger":"postgres","msg":"record","logging_pod":"pgv2-dev-11","record":{"log_time":"2024-04-30 20:40:31.614 UTC","process_id":"121","session_id":"6631573f.79","session_line_num":"2","session_start_time":"2024-04-30 20:40:31 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"08P01","message":"could not receive data from WAL stream: ERROR:  requested starting point 682/E4000000 is ahead of the WAL flush position of this server 682/E3000000","backend_type":"walreceiver","query_id":"0"}}
{"level":"debug","ts":"2024-04-30T20:40:31Z","msg":"Cached object request received","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:31Z","msg":"Cached object request received","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:32Z","msg":"Reconciling Cluster","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"00a69c30-b361-4731-81d6-d61d3b8fd1a0","caller":"internal/management/controller/instance_controller.go:111","logging_pod":"pgv2-dev-11","cluster":{"apiVersion":"postgresql.cnpg.io/v1","kind":"Cluster","namespace":"pgdb","name":"pgv2-dev"}}
{"level":"debug","ts":"2024-04-30T20:40:32Z","msg":"Reconciling custom monitoring queries","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"pgv2-dev","namespace":"pgdb"},"namespace":"pgdb","name":"pgv2-dev","reconcileID":"00a69c30-b361-4731-81d6-d61d3b8fd1a0","caller":"internal/management/controller/instance_controller.go:753","logging_pod":"pgv2-dev-11"}
{"level":"info","ts":"2024-04-30T20:40:32Z","logger":"wal-restore","msg":"WAL file not found in the recovery object store","logging_pod":"pgv2-dev-11","walName":"00000012.history","options":["--cloud-provider","aws-s3","s3://x319-cnpg-barman-bucket/","pgv2-dev"],"startTime":"2024-04-30T20:40:31Z","endTime":"2024-04-30T20:40:32Z","elapsedWalTime":0.344877257}
{"level":"debug","ts":"2024-04-30T20:40:32Z","msg":"Cached object request received","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11"}
{"level":"debug","ts":"2024-04-30T20:40:32Z","msg":"Cached object request received","caller":"pkg/management/log/log.go:178","logging_pod":"pgv2-dev-11"}

Code of Conduct

  • I agree to follow this project's Code of Conduct
@stevec-skyhawk stevec-skyhawk added the triage Pending triage label Apr 30, 2024
@ngoeddel-openi ngoeddel-openi mentioned this issue May 16, 2024
Open
4 tasks
@anthonator
Copy link

We are experiencing this same issue. @stevec-skyhawk did you manage to find a solution?

@stevec-skyhawk
Copy link
Author

We are experiencing this same issue. @stevec-skyhawk did you manage to find a solution?

No, we did not find a solution. We ended up having to create a new cluster through the recovery process.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@gbartolini gbartolini

Labels
triage Pending triage
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@gbartolini @anthonator @stevec-skyhawk