[Bug]: Replicas crash-loop when future timeline history files exist in WAL archive

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

Version

1.22.2

What version of Kubernetes are you using?

1.26

What is your Kubernetes environment?

Cloud: Amazon EKS

How did you install the operator?

Helm

What happened?

We are experiencing an issue with creating cluster replicas by scaling up the cluster resource. After finishing the phase of creating a backup with pg_basebackup it failed with the following error:
requested timeline 5 does not contain minimum recovery point 466/FD7555E8 on timeline 4. I have been attempting to create other replicas but it always failed on the same phase.

The cluster is currently on the following timeline:
Current Write LSN: 481/769AC000 (Timeline: 4 - WAL File: 000000040000048100000076)
Please let me know what additional information are required to help solve that issue.

Cluster resource

apiVersion: postgresql.cnpg.io/v1
kind: Cluster
metadata:
  annotations:
    cnpg.io/reloadedAt: "2024-03-29T11:07:33.020678+01:00"
    kubectl.kubernetes.io/restartedAt: "2024-03-29T11:52:20+01:00"
  creationTimestamp: "2024-03-29T11:17:22Z"
  generation: 7
  labels:
    argocd.argoproj.io/instance: prd-infra-eks-cnpg0-pg
  name: pg-database0
  namespace: cnpg1
  resourceVersion: "223159316"
  uid: cda6c776-0499-42bd-a7f2-14ac204ab15a
spec:
  affinity:
    nodeAffinity:
      requiredDuringSchedulingIgnoredDuringExecution:
        nodeSelectorTerms:
        - matchExpressions:
          - key: cnpg-workload-32
            operator: In
            values:
            - enabled
    podAntiAffinityType: preferred
    tolerations:
    - effect: NoSchedule
      key: cnpg-workload-32
      operator: Equal
      value: enabled
    topologyKey: topology.kubernetes.io/zone
  backup:
    barmanObjectStore:
      destinationPath: s3://prd-cnpg-backups/backups
      s3Credentials:
        inheritFromIAMRole: true
      wal:
        compression: gzip
        encryption: AES256
        maxParallel: 4
    retentionPolicy: 30d
    target: prefer-standby
    volumeSnapshot:
      className: pg-data-snapshot-class
      labels:
        app.kubernetes.io/managed-by: cloudnative-pg
      online: true
      onlineConfiguration:
        immediateCheckpoint: true
        waitForArchive: true
      snapshotOwnerReference: backup
      walClassName: pg-wal-snapshot-class
  bootstrap:
    initdb:
      dataChecksums: false
      database: app
      encoding: UTF8
      localeCType: C
      localeCollate: C
      owner: app
  enableSuperuserAccess: true
  failoverDelay: 0
  imageName: ecr-private-repo/infra/postgresql:13.11-10-202308231244
  imagePullPolicy: Always
  instances: 1
  logLevel: info
  maxSyncReplicas: 0
  minSyncReplicas: 0
  monitoring:
    customQueriesConfigMap:
    - key: queries
      name: cnpg-default-monitoring
    disableDefaultQueries: false
    enablePodMonitor: false
  postgresGID: 26
  postgresUID: 26
  postgresql:
    parameters:
      archive_mode: "on"
      archive_timeout: 5min
      auto_explain.log_min_duration: 10s
      autovacuum_analyze_scale_factor: "0.05"
      autovacuum_max_workers: "6"
      autovacuum_naptime: "30"
      autovacuum_vacuum_cost_delay: "20"
      autovacuum_vacuum_scale_factor: "0.1"
      checkpoint_completion_target: "0.9"
      checkpoint_timeout: "300"
      client_encoding: UTF8
      dynamic_shared_memory_type: posix
      effective_cache_size: 16GB
      huge_pages: "on"
      idle_in_transaction_session_timeout: "300000"
      log_checkpoints: "1"
      log_destination: csvlog
      log_directory: /controller/log
      log_filename: postgres
      log_hostname: "1"
      log_min_duration_statement: "5000"
      log_rotation_age: "0"
      log_rotation_size: "0"
      log_truncate_on_rotation: "false"
      logging_collector: "on"
      maintenance_work_mem: 1024MB
      max_connections: "2000"
      max_locks_per_transaction: "64"
      max_logical_replication_workers: "10"
      max_parallel_workers: "32"
      max_replication_slots: "10"
      max_stack_depth: "6144"
      max_sync_workers_per_subscription: "4"
      max_wal_senders: "20"
      max_wal_size: "2048"
      max_worker_processes: "15"
      min_wal_size: "192"
      pg_stat_statements.max: "10000"
      pg_stat_statements.track: all
      pgaudit.log: all, -misc
      pgaudit.log_catalog: "off"
      pgaudit.log_parameter: "on"
      pgaudit.log_relation: "on"
      shared_buffers: 4000MB
      shared_memory_type: mmap
      shared_preload_libraries: ""
      ssl_max_protocol_version: TLSv1.3
      ssl_min_protocol_version: TLSv1.3
      tcp_keepalives_count: "2"
      tcp_keepalives_idle: "300"
      tcp_keepalives_interval: "30"
      timezone: UTC
      track_activity_query_size: "2048"
      track_commit_timestamp: "on"
      track_io_timing: "on"
      wal_keep_size: 512MB
      wal_level: logical
      wal_receiver_timeout: 5s
      wal_sender_timeout: 5s
      work_mem: 32MB
    pg_hba:
    - hostssl app all all cert
    shared_preload_libraries:
    - pg_stat_statements
    - pg_stat_monitor
    - pg_qualstats
    - pg_stat_kcache
    - pg_wait_sampling
    - pgaudit
    - auto_explain
    syncReplicaElectionConstraint:
      enabled: false
  primaryUpdateMethod: restart
  primaryUpdateStrategy: unsupervised
  priorityClassName: infra-cluster-high
  replicationSlots:
    highAvailability:
      enabled: true
      slotPrefix: _cnpg_
    updateInterval: 30
  resources:
    limits:
      hugepages-2Mi: 5Gi
      memory: 25Gi
    requests:
      cpu: "7"
      hugepages-2Mi: 5Gi
      memory: 16Gi
  serviceAccountTemplate:
    metadata:
      annotations:
        eks.amazonaws.com/role-arn: arn:aws:iam::1234:role/eks-cnpg0-cloudnative-pg
  smartShutdownTimeout: 180
  startDelay: 3600
  stopDelay: 1800
  storage:
    resizeInUseVolumes: true
    size: 220Gi
    storageClass: io2-pg-data
  switchoverDelay: 3600
  walStorage:
    resizeInUseVolumes: true
    size: 200Gi
    storageClass: io2
status:
  availableArchitectures:
  - goArch: amd64
    hash: 72462f8f498e9a1e31eeb819b74038375e02b5bf3d5f9adb6016ab713c96d9dc
  - goArch: arm64
    hash: 14ec408750588c000a891253608b5f6a84cc436f607b99a6c15611b106136e44
  certificates:
    clientCASecret: pg-database0-ca
    expirations:
      pg-database0-ca: 2024-06-27 11:12:23 +0000 UTC
      pg-database0-replication: 2024-06-27 11:12:23 +0000 UTC
      pg-database0-server: 2024-06-27 11:12:23 +0000 UTC
    replicationTLSSecret: pg-database0-replication
    serverAltDNSNames:
    - pg-database0-rw
    - pg-database0-rw.cnpg1
    - pg-database0-rw.cnpg1.svc
    - pg-database0-r
    - pg-database0-r.cnpg1
    - pg-database0-r.cnpg1.svc
    - pg-database0-ro
    - pg-database0-ro.cnpg1
    - pg-database0-ro.cnpg1.svc
    serverCASecret: pg-database0-ca
    serverTLSSecret: pg-database0-server
  cloudNativePGCommitHash: bcdcd885
  cloudNativePGOperatorHash: 72462f8f498e9a1e31eeb819b74038375e02b5bf3d5f9adb6016ab713c96d9dc
  conditions:
  - lastTransitionTime: "2024-03-29T13:06:28Z"
    message: Cluster is Ready
    reason: ClusterIsReady
    status: "True"
    type: Ready
  - lastTransitionTime: "2024-03-29T11:18:08Z"
    message: Continuous archiving is working
    reason: ContinuousArchivingSuccess
    status: "True"
    type: ContinuousArchiving
  - lastTransitionTime: "2024-03-29T11:28:32Z"
    message: Backup was successful
    reason: LastBackupSucceeded
    status: "True"
    type: LastBackupSucceeded
  configMapResourceVersion:
    metrics:
      cnpg-default-monitoring: "174342296"
  currentPrimary: pg-database0-2
  currentPrimaryTimestamp: "2024-03-29T11:18:03.180909Z"
  firstRecoverabilityPoint: "2024-03-29T11:28:32Z"
  firstRecoverabilityPointByMethod:
    volumeSnapshot: "2024-03-29T11:28:32Z"
  healthyPVC:
  - pg-database0-2
  - pg-database0-2-wal
  instanceNames:
  - pg-database0-2
  instances: 1
  instancesReportedState:
    pg-database0-2:
      isPrimary: true
      timeLineID: 4
  instancesStatus:
    healthy:
    - pg-database0-2
  lastSuccessfulBackup: "2024-03-29T11:28:32Z"
  lastSuccessfulBackupByMethod:
    volumeSnapshot: "2024-03-29T11:28:32Z"
  latestGeneratedNode: 5
  managedRolesStatus: {}
  phase: Cluster in healthy state
  poolerIntegrations:
    pgBouncerIntegration:
      secrets:
      - pg-database0-pooler
  pvcCount: 2
  readService: pg-database0-r
  readyInstances: 1
  secretsResourceVersion:
    applicationSecretVersion: "223091672"
    clientCaSecretVersion: "223091668"
    replicationSecretVersion: "223091670"
    serverCaSecretVersion: "223091668"
    serverSecretVersion: "223091669"
    superuserSecretVersion: "223091671"
  targetPrimary: pg-database0-2
  timelineID: 4
  topology:
    instances:
      pg-database0-2: {}
    nodesUsed: 1
    successfullyExtracted: true
  writeService: pg-database0-rw

Relevant log output

{"level":"info","ts":"2024-03-29T11:58:29Z","logger":"postgres","msg":"record","logging_pod":"pg-database0-4","record":{"log_time":"2024-03-29 11:58:29.032 UTC","process_id":"27","session_id":"6606ace0.1b","session_line_num":"7","session_start_time":"2024-03-29 11:58:24 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"XX000","message":"requested timeline 5 is not a child of this server's history","detail":"Latest checkpoint is at 478/18379B60 on timeline 4, but in the history of the requested timeline, the server forked off from that timeline at 466/EB0000A0.","backend_type":"startup"}}

Code of Conduct

I agree to follow this project's Code of Conduct

It seems I have the same issue, with the same error. The restore starts well but at some point, the WAL may be corrupt or something:

{"level":"info","ts":"2024-05-22T13:23:41Z","logger":"wal-restore","msg":"Restored WAL file","logging_pod":"grafana-db-6","walName":"000000290000014B000000DE","startTime":"2024-05-22T13:23:35Z","endTime":"2024-05-22T13:23:41Z","elapsedWalTime":6.624312737}
{"level":"info","ts":"2024-05-22T13:23:41Z","logger":"wal-restore","msg":"WAL restore command completed (parallel)","logging_pod":"grafana-db-6","walName":"000000290000014B000000DE","maxParallel":1,"successfulWalRestore":1,"failedWalRestore":0,"endOfWALStream":false,"startTime":"2024-05-22T13:23:35Z","downloadStartTime":"2024-05-22T13:23:35Z","downloadTotalTime":6.624637657,"totalTime":6.73175157}
{"level":"info","ts":"2024-05-22T13:23:41Z","logger":"postgres","msg":"record","logging_pod":"grafana-db-6","record":{"log_time":"2024-05-22 13:23:41.900 UTC","process_id":"29","session_id":"664df1d0.1d","session_line_num":"6","session_start_time":"2024-05-22 13:23:28 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"restored log file \"000000290000014B000000DE\" from archive","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-05-22T13:23:41Z","logger":"postgres","msg":"record","logging_pod":"grafana-db-6","record":{"log_time":"2024-05-22 13:23:41.957 UTC","process_id":"29","session_id":"664df1d0.1d","session_line_num":"7","session_start_time":"2024-05-22 13:23:28 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"XX000","message":"requested timeline 42 is not a child of this server's history","detail":"Latest checkpoint is at 14B/DE002C40 on timeline 41, but in the history of the requested timeline, the server forked off from that timeline at 148/22081808.","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-05-22T13:23:41Z","logger":"postgres","msg":"record","logging_pod":"grafana-db-6","record":{"log_time":"2024-05-22 13:23:41.960 UTC","process_id":"25","session_id":"664df1d0.19","session_line_num":"6","session_start_time":"2024-05-22 13:23:28 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"startup process (PID 29) exited with exit code 1","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-05-22T13:23:41Z","logger":"postgres","msg":"record","logging_pod":"grafana-db-6","record":{"log_time":"2024-05-22 13:23:41.960 UTC","process_id":"25","session_id":"664df1d0.19","session_line_num":"7","session_start_time":"2024-05-22 13:23:28 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"aborting startup due to startup process failure","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-05-22T13:23:41Z","logger":"postgres","msg":"record","logging_pod":"grafana-db-6","record":{"log_time":"2024-05-22 13:23:41.963 UTC","process_id":"25","session_id":"664df1d0.19","session_line_num":"8","session_start_time":"2024-05-22 13:23:28 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"database system is shut down","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Extracting pg_controldata information","logging_pod":"grafana-db-6","reason":"postmaster has exited"}
{"level":"error","ts":"2024-05-22T13:23:41Z","msg":"PostgreSQL process exited with errors","logging_pod":"grafana-db-6","error":"exit status 1","stacktrace":"github.com/cloudnative-pg/cloudnative-pg/pkg/management/log.(*logger).Error\n\tpkg/management/log/log.go:125\ngithub.com/cloudnative-pg/cloudnative-pg/internal/cmd/manager/instance/run/lifecycle.(*PostgresLifecycle).Start\n\tinternal/cmd/manager/instance/run/lifecycle/lifecycle.go:98\nsigs.k8s.io/controller-runtime/pkg/manager.(*runnableGroup).reconcile.func1\n\tpkg/mod/sigs.k8s.io/[email protected]/pkg/manager/runnable_group.go:223"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Stopping and waiting for non leader election runnables"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Stopping and waiting for leader election runnables"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Shutdown signal received, waiting for all workers to finish","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Shutdown signal received, waiting for all workers to finish","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Shutdown signal received, waiting for all workers to finish","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"error","ts":"2024-05-22T13:23:41Z","msg":"error received after stop sequence was engaged","error":"exit status 1","stacktrace":"sigs.k8s.io/controller-runtime/pkg/manager.(*controllerManager).engageStopProcedure.func1\n\tpkg/mod/sigs.k8s.io/[email protected]/pkg/manager/internal.go:490"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Exited log pipe","fileName":"/controller/log/postgres.json","logging_pod":"grafana-db-6"}
{"level":"info","ts":"2024-05-22T13:23:41Z","logger":"roles_reconciler","msg":"Terminated RoleSynchronizer loop","logging_pod":"grafana-db-6"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Exited log pipe","fileName":"/controller/log/postgres","logging_pod":"grafana-db-6"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Exited log pipe","fileName":"/controller/log/postgres.csv","logging_pod":"grafana-db-6"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"All workers finished","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"All workers finished","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"All workers finished","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Webserver exited","logging_pod":"grafana-db-6","address":"localhost:8010"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Webserver exited","logging_pod":"grafana-db-6","address":":8000"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Webserver exited","logging_pod":"grafana-db-6","address":":9187"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Stopping and waiting for caches"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Stopping and waiting for webhooks"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: watch of *v1.Cluster ended with: an error on the server (\"unable to decode an event from the watch stream: context canceled\") has prevented the request from succeeding"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Stopping and waiting for HTTP servers"}
{"level":"info","ts":"2024-05-22T13:23:41Z","msg":"Wait completed, proceeding to shutdown the manager"}

I'm having the same issue, but not after replica rescaling. Instead, it started happening after scaling down all worker nodes to 0 and then back up to 3. 2 out of 3 replicas are running fine, but the third is unable to come up with the same logs as @sambonbonne.

+1, having the same problem in some of the clusters

The only reasonable workaround I've found for now is to run clusters with a maximum of 1 instance. This, of course, sacrifices availability. But as is evidenced by this issue, CNPG currently has severe correctness issues managing Postgres clusters with >0 replicas :(

So it's somehow related to backups.

Since new instance is being recreated using backups, I tried to remove/comment backup setup from cluster manifest, set the number of instances to one and applied. Deleted PVC of second instance. Then i scaled up to two replicas. New instance was replicated from primary node and both instances were fine. Then i re-enabled backup again and tried to restart second instance and it started failing again. So, i deleted the backups (it was just a test cluster) from S3 bucket and restarted second instance. Cluster is now running fine.

I experienced this on 1.24.0 today and can confirm that removing the backup config temporary enables to boot more replicas.

I encountered this issue on version 1.25.0 as well. To allow new replicas to run, I initially disabled the backup configuration. Interestingly, I have another cluster with backup enabled that has been running in production for over eight months without any issues.

The only difference in the backup configuration is:

wal:
  compression: gzip
  maxParallel: 8
  encryption: AES256

After noticing this, I re-enabled backups but removed these specific properties from the configuration. Since then, the cluster has remained stable for two consecutive days, successfully creating two daily scheduled backups and storing WALs in S3.

Hope this helps in diagnosing the issue! Let me know if I can provide any further details.

@ebodlli93

Nice catch, @ebodlli93

The only WAL config I had was as follows:

spec:
  backup:
    barmanObjectStore:
      wal:
        compression: bzip2

Removing that allowed me to resume scaling up replicas (instances: 2) in my PG clusters.

I also have bzip2 compression enabled on the base backups:

spec:
  backup:
    barmanObjectStore:
      data:
        compression: bzip2

I confirmed that keeping this enabled (whilst disabling the WAL compression) also works.

So it seems safe to say that the root cause here is specifically enabling compression on the WALs.

This issue is stale because it has been open for 60 days with no activity.

Not stale

I have same problem

I solved the issue.

You need to check the last history file on your primary ls -1 /var/lib/postgresql/wal/pg_wal/*.history. In my case it is /var/lib/postgresql/wal/pg_wal/00000015.history
Go to S3 storage and delete everything, which starts with next numbers: 00000016*, 00000017*, 00000018* and so on

Looks like it gets wrong history (which was canceled before) and fails

fix(walrestore): prevent replicas from downloading future timeline hi…

I solved the issue.

You need to check the last history file on your primary ls -1 /var/lib/postgresql/wal/pg_wal/*.history. In my case it is /var/lib/postgresql/wal/pg_wal/00000015.history

Go to S3 storage and delete everything, which starts with next numbers: 00000016*, 00000017*, 00000018* and so on

Looks like it gets wrong history (which was canceled before) and fails

This was very helpful, thank you!!

Navigation Menu

Repository navigation

[Bug]: Replicas crash-loop when future timeline history files exist in WAL archive #4188

Is there an existing issue already for this bug?

I have read the troubleshooting guide

I am running a supported version of CloudNativePG

Contact Details

Version

What version of Kubernetes are you using?

What is your Kubernetes environment?

How did you install the operator?

What happened?

Cluster resource

Relevant log output

Code of Conduct

20 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[Bug]: Replicas crash-loop when future timeline history files exist in WAL archive #4188

Description

Is there an existing issue already for this bug?

I have read the troubleshooting guide

I am running a supported version of CloudNativePG

Contact Details

Version

What version of Kubernetes are you using?

What is your Kubernetes environment?

How did you install the operator?

What happened?

Cluster resource

Relevant log output

Code of Conduct

Activity

cnd4 commented on May 22, 2024

XLordalX commented on Jun 10, 2024

mhkarimi1383 commented on Aug 10, 2024

samcday commented on Aug 10, 2024

MonolithProjects commented on Oct 1, 2024

zifeo commented on Jan 28, 2025

ebodlli93 commented on Feb 9, 2025

samcday commented on Mar 8, 2025

github-actions commented on May 10, 2025

Luminger commented on May 14, 2025

mequq commented on May 26, 2025

gugu commented on May 27, 2025

20 remaining items

aolear-ss commented on Feb 15, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions