[Bug]: Replica does not come up: checkpoint not found in timeline #4990
Description
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
No response
Version
1.23.2
What version of Kubernetes are you using?
1.28
What is your Kubernetes environment?
Other
How did you install the operator?
OLM
What happened?
We ran into a problem with WAL not being able to be shipped quick enough and it wanted to failover. This did not work (another now fixed bug report afair).
The replica failed and we destroyed the old replica and tried creating a new one. Unfortunately it always fails after the -init container finishes (successfully) when starting the replica (core-royalties-pg16-9).
The relevant log line might be
Latest checkpoint is at 19AA/14000060 on timeline 20, but in the history of the requested timeline, the server forked off from that timeline at 18FC/2E000110.
The primary server is pretty busy writing WAL, so it might just take too long. I don't know what to do though.
Cluster resource
apiVersion: postgresql.cnpg.io/v1
kind: Cluster
metadata:
annotations:
cnpg.io/reloadedAt: "2024-03-13T16:47:47.298812+01:00"
kubectl.kubernetes.io/restartedAt: "2024-03-13T17:03:56+01:00"
creationTimestamp: "2024-03-07T10:01:10Z"
generation: 14
name: core-royalties-pg16
namespace: db
resourceVersion: "562754887"
uid: b59ffc31-d8d9-4156-b18b-4c59d9d148ae
spec:
affinity:
nodeAffinity:
requiredDuringSchedulingIgnoredDuringExecution:
nodeSelectorTerms:
- matchExpressions:
- key: node-role.kubernetes.io/db
operator: Exists
podAntiAffinityType: required
tolerations:
- effect: NoSchedule
key: dedicated
operator: Equal
value: db
backup:
barmanObjectStore:
data:
compression: snappy
destinationPath: s3://db-core-royalties-wal/cnpg/core-royalties-pg16/
endpointURL: <redacted>
s3Credentials:
accessKeyId:
key: AWS_ACCESS_KEY_ID
name: core-royalties-wal
secretAccessKey:
key: AWS_SECRET_ACCESS_KEY
name: core-royalties-wal
wal:
compression: snappy
maxParallel: 4
retentionPolicy: 10d
target: prefer-standby
bootstrap:
initdb:
database: app
encoding: UTF8
localeCType: C
localeCollate: C
owner: app
enablePDB: true
enableSuperuserAccess: false
failoverDelay: 0
imageName: image-registry.openshift-image-registry.svc:5000/db/spilo-citus:16-20240604
instances: 2
logLevel: info
managed:
roles: [<redacted>]
maxSyncReplicas: 0
minSyncReplicas: 0
monitoring:
customQueriesConfigMap:
- key: queries
name: cnpg-default-monitoring
disableDefaultQueries: false
enablePodMonitor: true
nodeMaintenanceWindow:
inProgress: false
reusePVC: true
postgresGID: 26
postgresUID: 26
postgresql:
parameters:
archive_mode: "on"
archive_timeout: 5min
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"
max_connections: "1000"
max_parallel_workers: "32"
max_replication_slots: "32"
max_wal_size: "8192"
max_worker_processes: "32"
pg_stat_statements.track: all
shared_memory_type: mmap
shared_preload_libraries: ""
ssl_max_protocol_version: TLSv1.3
ssl_min_protocol_version: TLSv1.3
wal_keep_size: 512MB
wal_level: logical
wal_log_hints: "on"
wal_receiver_timeout: 5s
wal_sender_timeout: 5s
pg_hba:
- hostssl all all all scram-sha-256
shared_preload_libraries:
- citus
- pg_uuidv7
- pg_squeeze
syncReplicaElectionConstraint:
enabled: false
primaryUpdateMethod: restart
primaryUpdateStrategy: supervised
projectedVolumeTemplate:
sources:
- configMap:
items:
- key: archive_gzip.sh
mode: 365
path: scripts/archive_gzip.sh
- key: archive_zstd.sh
mode: 365
path: scripts/archive_zstd.sh
- key: head_gzip.sh
mode: 365
path: scripts/head_gzip.sh
- key: head_zstd.sh
mode: 365
path: scripts/head_zstd.sh
- key: unarchive_gzip.sh
mode: 365
path: scripts/unarchive_gzip.sh
- key: unarchive_zstd.sh
mode: 365
path: scripts/unarchive_zstd.sh
name: core-royalties-scripts
- configMap:
items:
- key: BUCKET_HOST
path: db-archives/BUCKET_HOST
- key: BUCKET_NAME
path: db-archives/BUCKET_NAME
- key: BUCKET_PORT
path: db-archives/BUCKET_PORT
- key: BUCKET_REGION
path: db-archives/BUCKET_REGION
- key: BUCKET_SUBREGION
path: db-archives/BUCKET_SUBREGION
name: core-royalties-db-archives
- secret:
items:
- key: AWS_ACCESS_KEY_ID
path: db-archives/AWS_ACCESS_KEY_ID
- key: AWS_SECRET_ACCESS_KEY
path: db-archives/AWS_SECRET_ACCESS_KEY
name: core-royalties-db-archives
replicationSlots:
highAvailability:
enabled: true
slotPrefix: _cnpg_
synchronizeReplicas:
enabled: true
updateInterval: 30
resources:
limits:
cpu: "18"
memory: 64Gi
requests:
cpu: "6"
memory: 32Gi
smartShutdownTimeout: 180
startDelay: 3600
stopDelay: 1800
storage:
resizeInUseVolumes: true
size: 1500Gi
storageClass: local-nvme
switchoverDelay: 3600
tablespaces:
- name: extended_storage
owner:
name: postgres
storage:
resizeInUseVolumes: true
size: 6Ti
storageClass: local-nvme
temporary: false
status:
availableArchitectures:
- goArch: amd64
hash: e43340cd2ccfa2a8120cf5de6035fe4b18d799bb2feabf99a91434dd9ba92e4c
- goArch: arm64
hash: f453a8cb50a418ff9cac24c818b9e155b80487b4152444e48d187161ecdfc0eb
certificates:
clientCASecret: core-royalties-pg16-ca
expirations:
core-royalties-pg16-ca: 2024-08-27 09:51:11 +0000 UTC
core-royalties-pg16-replication: 2024-08-27 09:51:11 +0000 UTC
core-royalties-pg16-server: 2024-08-27 09:51:11 +0000 UTC
replicationTLSSecret: core-royalties-pg16-replication
serverAltDNSNames:
- core-royalties-pg16-rw
- core-royalties-pg16-rw.db
- core-royalties-pg16-rw.db.svc
- core-royalties-pg16-r
- core-royalties-pg16-r.db
- core-royalties-pg16-r.db.svc
- core-royalties-pg16-ro
- core-royalties-pg16-ro.db
- core-royalties-pg16-ro.db.svc
serverCASecret: core-royalties-pg16-ca
serverTLSSecret: core-royalties-pg16-server
cloudNativePGCommitHash: 4bef8412
cloudNativePGOperatorHash: e43340cd2ccfa2a8120cf5de6035fe4b18d799bb2feabf99a91434dd9ba92e4c
conditions:
- lastTransitionTime: "2024-06-18T04:48:42Z"
message: Cluster Is Not Ready
reason: ClusterIsNotReady
status: "False"
type: Ready
- lastTransitionTime: "2024-06-18T04:48:45Z"
message: Continuous archiving is working
reason: ContinuousArchivingSuccess
status: "True"
type: ContinuousArchiving
- lastTransitionTime: "2024-07-01T05:26:05Z"
message: Backup was successful
reason: LastBackupSucceeded
status: "True"
type: LastBackupSucceeded
configMapResourceVersion:
metrics:
cnpg-default-monitoring: "525368161"
currentPrimary: core-royalties-pg16-4
currentPrimaryTimestamp: "2024-06-18T04:48:55.355761Z"
firstRecoverabilityPoint: "2024-06-21T04:24:49Z"
firstRecoverabilityPointByMethod:
barmanObjectStore: "2024-06-21T04:24:49Z"
healthyPVC:
- core-royalties-pg16-4
- core-royalties-pg16-4-tbs-extended-storage
- core-royalties-pg16-9
- core-royalties-pg16-9-tbs-extended-storage
image: image-registry.openshift-image-registry.svc:5000/db/spilo-citus:16-20240604
instanceNames:
- core-royalties-pg16-4
- core-royalties-pg16-9
instances: 2
instancesReportedState:
core-royalties-pg16-4:
isPrimary: true
timeLineID: 20
core-royalties-pg16-9:
isPrimary: false
instancesStatus:
healthy:
- core-royalties-pg16-4
replicating:
- core-royalties-pg16-9
jobCount: 4
lastFailedBackup: "2024-05-24T04:59:54Z"
lastSuccessfulBackup: "2024-07-01T05:25:59Z"
lastSuccessfulBackupByMethod:
barmanObjectStore: "2024-07-01T05:25:59Z"
latestGeneratedNode: 9
managedRolesStatus:
byStatus:
not-managed:
- bot-mmp-syncer-core-royalties
- bot-download-proxy
- bot-discogs-syncer
- api-core-royalties
- bot-winline-syncer
- bot-royalty-distribution-calculator
- robot_zmon
- standby
- bot-statement-downloader
- bot-statement-exporter
- bot-statement-ingestor
- bot-statement-sampler
- bot-external-ems-trend-data-brigde
- bot-browser-automation
- bot-sms-gateway
- bot-smtp-gateway
- bot-analytics-db-syncer
- usergroup-read-nearly-all
- bot-royalty-distribution-report-generator
- bot-db-cron-core-royalties
- mara.hartung
- bot-royalty-distribution-report-email-sender
- bot-analytics-data-exporter
- api-dec
- app
reconciled:
- alexander.kops
- ante.von.postel
- bot-fxrates-scraper
- max
- michi
- jens
- tob
- nicolai.hallberg
- wolfgang.stoelzle
- lucie.abendroth
- jan.kuechler
- mika
- tobias
- frauke.schmidt
- ilbey.bulut
- dan
- juergen.soeder
reserved:
- postgres
- streaming_replica
passwordStatus:
alexander.kops:
transactionID: 315504
ante.von.postel:
transactionID: 315505
bot-fxrates-scraper:
resourceVersion: "453797026"
transactionID: 384346
dan:
transactionID: 315519
frauke.schmidt:
transactionID: 315517
ilbey.bulut:
transactionID: 315518
jan.kuechler:
transactionID: 1749386
jens:
transactionID: 315509
juergen.soeder:
transactionID: 315506
lucie.abendroth:
transactionID: 315513
max:
transactionID: 315507
michi:
transactionID: 315508
mika:
transactionID: 315515
nicolai.hallberg:
transactionID: 315511
tob:
transactionID: 315510
tobias:
transactionID: 315516
wolfgang.stoelzle:
transactionID: 315512
onlineUpdateEnabled: true
phase: Waiting for the instances to become active
phaseReason: Some instances are not yet active. Please wait.
poolerIntegrations:
pgBouncerIntegration: {}
pvcCount: 4
readService: core-royalties-pg16-r
readyInstances: 1
secretsResourceVersion:
applicationSecretVersion: "547666968"
clientCaSecretVersion: "535433707"
managedRoleSecretVersion:
bot-fxrates-scraper-core-royalties-pgcreds: "453797026"
replicationSecretVersion: "535433709"
serverCaSecretVersion: "535433707"
serverSecretVersion: "535433708"
switchReplicaClusterStatus: {}
tablespacesStatus:
- name: extended_storage
owner: postgres
state: reconciled
targetPrimary: core-royalties-pg16-4
targetPrimaryTimestamp: "2024-06-18T04:48:49.629562Z"
timelineID: 20
topology:
instances:
core-royalties-pg16-4: {}
core-royalties-pg16-9: {}
nodesUsed: 2
successfullyExtracted: true
writeService: core-royalties-pg16-rwRelevant log output
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"setup","msg":"Starting CloudNativePG Instance Manager","logging_pod":"core-royalties-pg16-9","version":"1.23.2","build":{"Version":"1.23.2","Commit":"4bef8412","Date":"2024-06-12"}}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"setup","msg":"starting tablespace manager","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"setup","msg":"starting external server manager","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"setup","msg":"starting controller-runtime manager","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Starting EventSource","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","source":"kind source: *v1.Cluster"}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Starting Controller","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"roles_reconciler","msg":"starting up the runnable","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Starting webserver","logging_pod":"core-royalties-pg16-9","address":":9187"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"roles_reconciler","msg":"skipping the RoleSynchronizer in replicas","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"roles_reconciler","msg":"setting up RoleSynchronizer loop","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Starting webserver","logging_pod":"core-royalties-pg16-9","address":"localhost:8010"}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Starting EventSource","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","source":"kind source: *v1.Cluster"}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Starting Controller","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Starting EventSource","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","source":"kind source: *v1.Cluster"}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Starting Controller","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Starting webserver","logging_pod":"core-royalties-pg16-9","address":":8000"}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Starting workers","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","worker count":1}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Starting workers","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","worker count":1}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Starting workers","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","worker count":1}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Found previous run flag","logging_pod":"core-royalties-pg16-9","filename":"/var/lib/postgresql/data/pgdata/cnpg_initialized-core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Extracting pg_controldata information","logging_pod":"core-royalties-pg16-9","reason":"postmaster start up"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"pg_controldata","msg":"pg_control version number: 1300\nCatalog version number: 202307071\nDatabase system identifier: 7342071844302868515\nDatabase cluster state: in production\npg_control last modified: Mon 01 Jul 2024 01:39:49 PM UTC\nLatest checkpoint location: 19AA/14000060\nLatest checkpoint's REDO location: 19AA/14000028\nLatest checkpoint's REDO WAL file: 00000014000019AA00000014\nLatest checkpoint's TimeLineID: 20\nLatest checkpoint's PrevTimeLineID: 20\nLatest checkpoint's full_page_writes: on\nLatest checkpoint's NextXID: 0:3739416\nLatest checkpoint's NextOID: 185538614\nLatest checkpoint's NextMultiXactId: 75910\nLatest checkpoint's NextMultiOffset: 234941\nLatest checkpoint's oldestXID: 722\nLatest checkpoint's oldestXID's DB: 5\nLatest checkpoint's oldestActiveXID: 3739416\nLatest checkpoint's oldestMultiXid: 1\nLatest checkpoint's oldestMulti's DB: 16489\nLatest checkpoint's oldestCommitTsXid:0\nLatest checkpoint's newestCommitTsXid:0\nTime of latest checkpoint: Mon 01 Jul 2024 01:39:48 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: 1000\nmax_worker_processes setting: 32\nmax_wal_senders setting: 10\nmax_prepared_xacts setting: 2000\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: cb3f9f6c33cfd47dd626988e8ae23202776f4f80fae330eef968882da2143f71\n","pipe":"stdout","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"postgres","msg":"2024-07-01 16:03:22.269 UTC [35] LOG: number of prepared transactions has not been configured, overriding","pipe":"stderr","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"postgres","msg":"2024-07-01 16:03:22.269 UTC [35] DETAIL: max_prepared_transactions is now set to 2000","pipe":"stderr","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","msg":"Instance is still down, will retry in 1 second","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"core-royalties-pg16","namespace":"db"},"namespace":"db","name":"core-royalties-pg16","reconcileID":"a284d17d-18a2-4c82-b595-323209904e09","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"postgres","msg":"2024-07-01 16:03:22.296 UTC [35] LOG: redirecting log output to logging collector process","pipe":"stderr","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"postgres","msg":"2024-07-01 16:03:22.296 UTC [35] HINT: Future log output will appear in directory \"/controller/log\".","pipe":"stderr","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"postgres","msg":"2024-07-01 16:03:22.296 UTC [35] LOG: ending log output to stderr","source":"/controller/log/postgres","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"postgres","msg":"2024-07-01 16:03:22.296 UTC [35] HINT: Future log output will go to log destination \"csvlog\".","source":"/controller/log/postgres","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:22.296 UTC","process_id":"35","session_id":"6682d34a.23","session_line_num":"1","session_start_time":"2024-07-01 16:03:22 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-07-01T16:03:22Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:22.296 UTC","process_id":"35","session_id":"6682d34a.23","session_line_num":"2","session_start_time":"2024-07-01 16:03:22 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"starting PostgreSQL 16.3 (Debian 16.3-1.pgdg120+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 12.2.0-14) 12.2.0, 64-bit","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:22.296 UTC","process_id":"35","session_id":"6682d34a.23","session_line_num":"3","session_start_time":"2024-07-01 16:03:22 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-07-01T16:03:22Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:22.296 UTC","process_id":"35","session_id":"6682d34a.23","session_line_num":"4","session_start_time":"2024-07-01 16:03:22 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-07-01T16:03:22Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:22.297 UTC","process_id":"35","session_id":"6682d34a.23","session_line_num":"5","session_start_time":"2024-07-01 16:03:22 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-07-01T16:03:22Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:22.299 UTC","process_id":"39","session_id":"6682d34a.27","session_line_num":"1","session_start_time":"2024-07-01 16:03:22 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"database system was interrupted; last known up at 2024-07-01 13:39:49 UTC","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"wal-restore","msg":"Restored WAL file","logging_pod":"core-royalties-pg16-9","walName":"00000015.history","startTime":"2024-07-01T16:03:22Z","endTime":"2024-07-01T16:03:22Z","elapsedWalTime":0.31691575}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"wal-restore","msg":"WAL restore command completed (parallel)","logging_pod":"core-royalties-pg16-9","walName":"00000015.history","maxParallel":4,"successfulWalRestore":1,"failedWalRestore":3,"endOfWALStream":false,"startTime":"2024-07-01T16:03:22Z","downloadStartTime":"2024-07-01T16:03:22Z","downloadTotalTime":0.317032751,"totalTime":0.365500254}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:22.695 UTC","process_id":"39","session_id":"6682d34a.27","session_line_num":"2","session_start_time":"2024-07-01 16:03:22 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"restored log file \"00000015.history\" from archive","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-07-01T16:03:22Z","logger":"wal-restore","msg":"WAL file not found in the recovery object store","logging_pod":"core-royalties-pg16-9","walName":"00000016.history","options":["--endpoint-url","<redacted>","--cloud-provider","aws-s3","s3://db-core-royalties-wal/cnpg/core-royalties-pg16/","core-royalties-pg16"],"startTime":"2024-07-01T16:03:22Z","endTime":"2024-07-01T16:03:22Z","elapsedWalTime":0.228545702}
{"level":"info","ts":"2024-07-01T16:03:23Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:23.011 UTC","user_name":"postgres","database_name":"postgres","process_id":"84","connection_from":"[local]","session_id":"6682d34b.54","session_line_num":"1","session_start_time":"2024-07-01 16:03:23 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-07-01T16:03:23Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:23.081 UTC","process_id":"39","session_id":"6682d34a.27","session_line_num":"3","session_start_time":"2024-07-01 16:03:22 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"entering standby mode","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-07-01T16:03:23Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:23.081 UTC","process_id":"39","session_id":"6682d34a.27","session_line_num":"4","session_start_time":"2024-07-01 16:03:22 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"starting backup recovery with redo LSN 19AA/12000028, checkpoint LSN 19AA/12000060, on timeline ID 20","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-07-01T16:03:23Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:23.303 UTC","user_name":"postgres","database_name":"postgres","process_id":"108","connection_from":"[local]","session_id":"6682d34b.6c","session_line_num":"1","session_start_time":"2024-07-01 16:03:23 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-07-01T16:03:23Z","msg":"DB not available, will retry","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster","Cluster":{"name":"core-royalties-pg16","namespace":"db"},"namespace":"db","name":"core-royalties-pg16","reconcileID":"395b52c2-e5b3-4193-8d79-b1bc912a22e1","logging_pod":"core-royalties-pg16-9","err":"failed to connect to `user=postgres database=postgres`: /controller/run/.s.PGSQL.5432 (/controller/run): server error: FATAL: the database system is starting up (SQLSTATE 57P03)"}
{"level":"info","ts":"2024-07-01T16:03:23Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:23.304 UTC","user_name":"postgres","database_name":"postgres","process_id":"109","connection_from":"[local]","session_id":"6682d34b.6d","session_line_num":"1","session_start_time":"2024-07-01 16:03:23 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-07-01T16:03:23Z","logger":"wal-restore","msg":"Restored WAL file","logging_pod":"core-royalties-pg16-9","walName":"00000015.history","startTime":"2024-07-01T16:03:23Z","endTime":"2024-07-01T16:03:23Z","elapsedWalTime":0.221317728}
{"level":"info","ts":"2024-07-01T16:03:23Z","logger":"wal-restore","msg":"WAL restore command completed (parallel)","logging_pod":"core-royalties-pg16-9","walName":"00000015.history","maxParallel":4,"successfulWalRestore":1,"failedWalRestore":3,"endOfWALStream":false,"startTime":"2024-07-01T16:03:23Z","downloadStartTime":"2024-07-01T16:03:23Z","downloadTotalTime":0.22145703,"totalTime":0.268732854}
{"level":"info","ts":"2024-07-01T16:03:23Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:23.362 UTC","process_id":"39","session_id":"6682d34a.27","session_line_num":"5","session_start_time":"2024-07-01 16:03:22 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"restored log file \"00000015.history\" from archive","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-07-01T16:03:23Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:23.414 UTC","user_name":"postgres","database_name":"postgres","process_id":"131","connection_from":"[local]","session_id":"6682d34b.83","session_line_num":"1","session_start_time":"2024-07-01 16:03:23 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-07-01T16:03:23Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:23.648 UTC","user_name":"postgres","database_name":"postgres","process_id":"136","connection_from":"[local]","session_id":"6682d34b.88","session_line_num":"1","session_start_time":"2024-07-01 16:03:23 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-07-01T16:03:23Z","logger":"wal-restore","msg":"WAL file not found in the recovery object store","logging_pod":"core-royalties-pg16-9","walName":"00000015000019AA00000012","options":["--endpoint-url","<redacted>","--cloud-provider","aws-s3","s3://db-core-royalties-wal/cnpg/core-royalties-pg16/","core-royalties-pg16"],"startTime":"2024-07-01T16:03:23Z","endTime":"2024-07-01T16:03:23Z","elapsedWalTime":0.277760957}
{"level":"info","ts":"2024-07-01T16:03:24Z","logger":"wal-restore","msg":"Restored WAL file","logging_pod":"core-royalties-pg16-9","walName":"00000014000019AA00000015","startTime":"2024-07-01T16:03:23Z","endTime":"2024-07-01T16:03:24Z","elapsedWalTime":0.27732838}
{"level":"info","ts":"2024-07-01T16:03:24Z","logger":"wal-restore","msg":"Restored WAL file","logging_pod":"core-royalties-pg16-9","walName":"00000014000019AA00000014","startTime":"2024-07-01T16:03:23Z","endTime":"2024-07-01T16:03:24Z","elapsedWalTime":0.299597147}
{"level":"info","ts":"2024-07-01T16:03:24Z","logger":"wal-restore","msg":"Restored WAL file","logging_pod":"core-royalties-pg16-9","walName":"00000014000019AA00000013","startTime":"2024-07-01T16:03:23Z","endTime":"2024-07-01T16:03:24Z","elapsedWalTime":0.300367211}
{"level":"info","ts":"2024-07-01T16:03:24Z","logger":"wal-restore","msg":"Restored WAL file","logging_pod":"core-royalties-pg16-9","walName":"00000014000019AA00000012","startTime":"2024-07-01T16:03:23Z","endTime":"2024-07-01T16:03:24Z","elapsedWalTime":0.313373012}
{"level":"info","ts":"2024-07-01T16:03:24Z","logger":"wal-restore","msg":"WAL restore command completed (parallel)","logging_pod":"core-royalties-pg16-9","walName":"00000014000019AA00000012","maxParallel":4,"successfulWalRestore":4,"failedWalRestore":0,"endOfWALStream":false,"startTime":"2024-07-01T16:03:23Z","downloadStartTime":"2024-07-01T16:03:23Z","downloadTotalTime":0.313483181,"totalTime":0.360317842}
{"level":"info","ts":"2024-07-01T16:03:24Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:24.169 UTC","process_id":"39","session_id":"6682d34a.27","session_line_num":"6","session_start_time":"2024-07-01 16:03:22 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"restored log file \"00000014000019AA00000012\" from archive","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-07-01T16:03:24Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:24.176 UTC","process_id":"39","session_id":"6682d34a.27","session_line_num":"7","session_start_time":"2024-07-01 16:03:22 UTC","transaction_id":"0","error_severity":"FATAL","sql_state_code":"XX000","message":"requested timeline 21 is not a child of this server's history","detail":"Latest checkpoint is at 19AA/14000060 on timeline 20, but in the history of the requested timeline, the server forked off from that timeline at 18FC/2E000110.","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-07-01T16:03:24Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:24.177 UTC","process_id":"35","session_id":"6682d34a.23","session_line_num":"6","session_start_time":"2024-07-01 16:03:22 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"startup process (PID 39) exited with exit code 1","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-07-01T16:03:24Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:24.177 UTC","process_id":"35","session_id":"6682d34a.23","session_line_num":"7","session_start_time":"2024-07-01 16:03:22 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-07-01T16:03:24Z","logger":"postgres","msg":"record","logging_pod":"core-royalties-pg16-9","record":{"log_time":"2024-07-01 16:03:24.180 UTC","process_id":"35","session_id":"6682d34a.23","session_line_num":"8","session_start_time":"2024-07-01 16:03:22 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-07-01T16:03:24Z","msg":"Extracting pg_controldata information","logging_pod":"core-royalties-pg16-9","reason":"postmaster has exited"}
{"level":"error","ts":"2024-07-01T16:03:24Z","msg":"PostgreSQL process exited with errors","logging_pod":"core-royalties-pg16-9","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:106\nsigs.k8s.io/controller-runtime/pkg/manager.(*runnableGroup).reconcile.func1\n\tpkg/mod/sigs.k8s.io/controller-runtime@v0.18.3/pkg/manager/runnable_group.go:226"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Stopping and waiting for non leader election runnables"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Stopping and waiting for leader election runnables"}
{"level":"error","ts":"2024-07-01T16:03:24Z","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/controller-runtime@v0.18.3/pkg/manager/internal.go:499"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Shutdown signal received, waiting for all workers to finish","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Shutdown signal received, waiting for all workers to finish","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Exited log pipe","fileName":"/controller/log/postgres.csv","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Exited log pipe","fileName":"/controller/log/postgres.json","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Webserver exited","logging_pod":"core-royalties-pg16-9","address":":9187"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Webserver exited","logging_pod":"core-royalties-pg16-9","address":"localhost:8010"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Exited log pipe","fileName":"/controller/log/postgres","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:24Z","logger":"roles_reconciler","msg":"Terminated RoleSynchronizer loop","logging_pod":"core-royalties-pg16-9"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"All workers finished","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Shutdown signal received, waiting for all workers to finish","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Webserver exited","logging_pod":"core-royalties-pg16-9","address":":8000"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"All workers finished","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"All workers finished","controller":"cluster","controllerGroup":"postgresql.cnpg.io","controllerKind":"Cluster"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Stopping and waiting for caches"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Stopping and waiting for webhooks"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Stopping and waiting for HTTP servers"}
{"level":"info","ts":"2024-07-01T16:03:24Z","msg":"Wait completed, proceeding to shutdown the manager"}
{"level":"info","ts":"2024-07-01T16:03:24Z","logger":"pg_controldata","msg":"pg_control version number: 1300\nCatalog version number: 202307071\nDatabase system identifier: 7342071844302868515\nDatabase cluster state: in production\npg_control last modified: Mon 01 Jul 2024 01:39:49 PM UTC\nLatest checkpoint location: 19AA/14000060\nLatest checkpoint's REDO location: 19AA/14000028\nLatest checkpoint's REDO WAL file: 00000014000019AA00000014\nLatest checkpoint's TimeLineID: 20\nLatest checkpoint's PrevTimeLineID: 20\nLatest checkpoint's full_page_writes: on\nLatest checkpoint's NextXID: 0:3739416\nLatest checkpoint's NextOID: 185538614\nLatest checkpoint's NextMultiXactId: 75910\nLatest checkpoint's NextMultiOffset: 234941\nLatest checkpoint's oldestXID: 722\nLatest checkpoint's oldestXID's DB: 5\nLatest checkpoint's oldestActiveXID: 3739416\nLatest checkpoint's oldestMultiXid: 1\nLatest checkpoint's oldestMulti's DB: 16489\nLatest checkpoint's oldestCommitTsXid:0\nLatest checkpoint's newestCommitTsXid:0\nTime of latest checkpoint: Mon 01 Jul 2024 01:39:48 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: 1000\nmax_worker_processes setting: 32\nmax_wal_senders setting: 10\nmax_prepared_xacts setting: 2000\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: cb3f9f6c33cfd47dd626988e8ae23202776f4f80fae330eef968882da2143f71\n","pipe":"stdout","logging_pod":"core-royalties-pg16-9"}Code of Conduct
- I agree to follow this project's Code of Conduct