search

patroni / patroni

A template for PostgreSQL High Availability with Etcd, Consul, ZooKeeper, or Kubernetes
MIT License
6.78k stars 843 forks source link

Failed to determine PostgreSQL state from the connection #3053

Closed DumitruNiculai closed 6 months ago

DumitruNiculai commented 6 months ago

What happened?

We are running High Availability PostgreSQL cluster with patroni.

After we deployed Replica node, it remains in "starting" state for quite a long time, 2-3-4 hours. Then it changes to normal state "running"

The same happenes even after we simply restart Patroni for replica node

We tried to install the latest version of Patroni 3.2.2, that the issue remains the same

How can we reproduce it (as minimally and precisely as possible)?

The issue appears on Replica node start up

What did you expect to happen?

Cluster should start normally without a long time to wait

Patroni/PostgreSQL/DCS version

Patroni configuration file

---

scope: crgdb-pg-cluster-pr1
name: kz-bss-crgdb02
namespace: /service-pr1/

restapi:
  listen: 10.172.235.24:8008
  connect_address: 10.172.235.24:8008
  certfile: /etc/ssl/certs/patroni-api-prod.pem
  cafile: /etc/ssl/certs/patroni-api-ca-prod.pem
  verify_client: required

#ctl:
#  insecure: false
#  certfile: /etc/ssl/certs/patroni-api-prod.pem
#  cafile: /etc/ssl/certs/patroni-api-ca-prod.pem

log:
  level: WARNING
  format: '%(asctime)s %(levelname)s: %(message)s'
  dateformat: ''
  max_queue_size: 1000
  dir: /var/log/patroni
  file_num: 4
  file_size: 25000000
  loggers:
    postgres.postmaster: WARNING
    urllib3: DEBUG

etcd:
  hosts:
  - 10.172.235.16:2379
  - 10.172.235.17:2379
  - 10.172.235.18:2379
  protocol: https
  cacert: /etc/ssl/certs/ca.pem
  cert: /etc/ssl/certs/etcd.pem
  key: /etc/ssl/certs/etcd-key.pem

bootstrap:
  method: initdb
  dcs:
    ttl: 30
    loop_wait: 10
    retry_timeout: 10
    maximum_lag_on_failover: 1048576
    master_start_timeout: 300
    synchronous_mode: true
    synchronous_mode_strict: false
    synchronous_node_count: 1
    # standby_cluster:
      # host: 127.0.0.1
      # port: 1111
      # primary_slot_name: patroni
    postgresql:
      use_pg_rewind: true
      use_slots: true
      parameters:
        archive_command: pgbackrest --stanza=PgDb_13.4 archive-push %p
        archive_mode: true
        archive_timeout: 1800s
        auto_explain.log_analyze: true
        auto_explain.log_buffers: true
        auto_explain.log_min_duration: 10s
        auto_explain.log_nested_statements: true
        auto_explain.log_timing: false
        auto_explain.log_triggers: true
        auto_explain.log_verbose: true
        autovacuum: true
        autovacuum_analyze_scale_factor: 0.02
        autovacuum_max_workers: 5
        autovacuum_naptime: 1s
        autovacuum_vacuum_cost_delay: 20
        autovacuum_vacuum_cost_limit: 200
        autovacuum_vacuum_scale_factor: 0.01
        checkpoint_completion_target: 0.7
        checkpoint_timeout: 15min
        default_statistics_target: 100
        effective_cache_size: 55GB
        effective_io_concurrency: 2
        hot_standby: true
        huge_pages: try
        idle_in_transaction_session_timeout: 3600s
        log_checkpoints: true
        log_directory: /pgcluster/pgdata/13.4/log
        log_filename: postgresql-%a.log
        log_line_prefix: '%t [%p-%l] %r %q%u@%d '
        log_lock_waits: true
        log_rotation_age: 1d
        log_rotation_size: 0
        log_temp_files: 0
        log_truncate_on_rotation: true
        logging_collector: true
        maintenance_work_mem: 2GB
        max_connections: 11000
        max_files_per_process: 4096
        max_locks_per_transaction: 100
        max_parallel_maintenance_workers: 2
        max_parallel_workers: 24
        max_parallel_workers_per_gather: 4
        max_replication_slots: 10
        max_wal_senders: 10
        max_wal_size: 16GB
        max_worker_processes: 24
        min_wal_size: 2GB
        pg_stat_statements.max: 10000
        pg_stat_statements.save: false
        pg_stat_statements.track: all
        random_page_cost: 1.1
        seq_page_cost: 1
        shared_buffers: 20GB
        shared_preload_libraries: pg_stat_statements,auto_explain
        superuser_reserved_connections: 5
        synchronous_commit: true
        track_activities: true
        track_counts: true
        track_functions: all
        track_io_timing: true
        wal_buffers: 64MB
        wal_keep_segments: 130
        wal_level: logical
        wal_log_hints: true
        work_mem: 12MB

  initdb:  # List options to be passed on to initdb
    - encoding: UTF8
    - data-checksums

  pg_hba:  # Add following lines to pg_hba.conf after running 'initdb'
    - host replication replicator 127.0.0.1/32 md5
    - host replication replicator 10.172.235.23/32 md5
    - host replication replicator 10.172.235.24/32 md5
    - host all all 10.172.235.19/32 md5
    - host all all 10.172.235.20/32 md5
    - host all all 0.0.0.0/0 md5

postgresql:
  listen: 0.0.0.0:5432
  connect_address: 10.172.235.24:5432
  use_unix_socket: true
  data_dir: /pgcluster/pgdata/13.4/data
  bin_dir: /usr/pgsql-13/bin
  config_dir: /pgcluster/pgdata/13.4/data/
  pgpass: /tmp/pgpass
  authentication:
    replication:
      username: replicator
      password: Replicator
    superuser:
      username: postgres
      password: P@stgres1
    rewind:  # Has no effect on postgres 10 and lower
      username: rewind_user
      password: rewind_password
  parameters:
    unix_socket_directories: /var/run/postgresql

watchdog:
  mode: off  # Allowed values: off, automatic, required
  device: /dev/watchdog
  safety_margin: 5

tags:
  nofailover: false
  noloadbalance: false
  clonefrom: false
  nosync: false

patronictl show-config

loop_wait: 10
maximum_lag_on_failover: 1048576
postgresql:
  parameters:
    archive_command: pgbackrest --stanza=PgDb_13.4 archive-push %p
    archive_mode: true
    archive_timeout: 1800s
    auto_explain.log_analyze: true
    auto_explain.log_buffers: true
    auto_explain.log_min_duration: 10s
    auto_explain.log_nested_statements: true
    auto_explain.log_timing: false
    auto_explain.log_triggers: true
    auto_explain.log_verbose: true
    autovacuum: true
    autovacuum_analyze_scale_factor: 0.02
    autovacuum_max_workers: 5
    autovacuum_naptime: 1s
    autovacuum_vacuum_cost_delay: 20
    autovacuum_vacuum_cost_limit: 200
    autovacuum_vacuum_scale_factor: 0.01
    checkpoint_completion_target: 0.7
    checkpoint_timeout: 15min
    default_statistics_target: 100
    effective_cache_size: 55GB
    effective_io_concurrency: 2
    hot_standby: true
    huge_pages: try
    idle_in_transaction_session_timeout: 3600s
    log_checkpoints: true
    log_directory: /pgcluster/pgdata/13.4/log
    log_filename: postgresql-%a.log
    log_line_prefix: '%t [%p-%l] %r %q%u@%d '
    log_lock_waits: true
    log_rotation_age: 1d
    log_rotation_size: 0
    log_temp_files: 0
    log_truncate_on_rotation: true
    logging_collector: true
    maintenance_work_mem: 2GB
    max_connections: 11000
    max_files_per_process: 4096
    max_locks_per_transaction: 100
    max_parallel_maintenance_workers: 2
    max_parallel_workers: 24
    max_parallel_workers_per_gather: 4
    max_replication_slots: 10
    max_wal_senders: 10
    max_wal_size: 16GB
    max_worker_processes: 24
    min_wal_size: 2GB
    pg_stat_statements.max: 10000
    pg_stat_statements.save: false
    pg_stat_statements.track: all
    random_page_cost: 1.1
    seq_page_cost: 1
    shared_buffers: 20GB
    shared_preload_libraries: pg_stat_statements,auto_explain
    superuser_reserved_connections: 5
    synchronous_commit: true
    track_activities: true
    track_counts: true
    track_functions: all
    track_io_timing: true
    wal_buffers: 64MB
    wal_keep_segments: 130
    wal_level: logical
    wal_log_hints: true
    work_mem: 12MB
  use_pg_rewind: true
  use_slots: true
retry_timeout: 10
synchronous_mode: true
synchronous_mode_strict: false
synchronous_node_count: 1
ttl: 30

Patroni log files

2024-04-19 10:42:22,776 DEBUG: https://10.172.235.17:2379 "PUT /v2/keys/service-pr1/crgdb-pg-cluster-pr1/members/kz-bss-crgdb02 HTTP/1.1" 200 747
2024-04-19 10:42:32,766 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
2024-04-19 10:42:32,770 DEBUG: https://10.172.235.17:2379 "GET /v2/keys/service-pr1/crgdb-pg-cluster-pr1/?recursive=true HTTP/1.1" 200 None
2024-04-19 10:42:32,772 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
2024-04-19 10:42:32,776 DEBUG: https://10.172.235.17:2379 "PUT /v2/keys/service-pr1/crgdb-pg-cluster-pr1/members/kz-bss-crgdb02 HTTP/1.1" 200 747
2024-04-19 10:42:42,766 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
2024-04-19 10:42:42,769 DEBUG: https://10.172.235.17:2379 "GET /v2/keys/service-pr1/crgdb-pg-cluster-pr1/?recursive=true HTTP/1.1" 200 None
2024-04-19 10:42:42,961 WARNING: Retry got exception: 'connection problems'
2024-04-19 10:42:42,962 WARNING: Failed to determine PostgreSQL state from the connection, falling back to cached role
2024-04-19 10:42:42,965 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
2024-04-19 10:42:42,971 DEBUG: https://10.172.235.17:2379 "PUT /v2/keys/service-pr1/crgdb-pg-cluster-pr1/members/kz-bss-crgdb02 HTTP/1.1" 200 747
2024-04-19 10:42:42,972 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
2024-04-19 10:42:42,973 DEBUG: https://10.172.235.17:2379 "GET /v2/keys/service-pr1/crgdb-pg-cluster-pr1/leader?wait=true&waitIndex=28274204 HTTP/1.1" 200 None
2024-04-19 10:42:44,979 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
2024-04-19 10:42:44,982 DEBUG: https://10.172.235.17:2379 "GET /v2/keys/service-pr1/crgdb-pg-cluster-pr1/?recursive=true HTTP/1.1" 200 None
2024-04-19 10:42:45,606 WARNING: Retry got exception: 'connection problems'
2024-04-19 10:42:45,607 WARNING: Failed to determine PostgreSQL state from the connection, falling back to cached role
2024-04-19 10:42:45,610 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
2024-04-19 10:42:45,614 DEBUG: https://10.172.235.17:2379 "PUT /v2/keys/service-pr1/crgdb-pg-cluster-pr1/members/kz-bss-crgdb02 HTTP/1.1" 200 747
2024-04-19 10:42:45,615 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
2024-04-19 10:42:45,616 DEBUG: https://10.172.235.17:2379 "GET /v2/keys/service-pr1/crgdb-pg-cluster-pr1/leader?wait=true&waitIndex=28274211 HTTP/1.1" 200 None
2024-04-19 10:42:54,978 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
2024-04-19 10:42:54,981 DEBUG: https://10.172.235.17:2379 "GET /v2/keys/service-pr1/crgdb-pg-cluster-pr1/?recursive=true HTTP/1.1" 200 None

PostgreSQL log files

2024-04-19 10:41:33 +06 [2464031-3]  LOG:  redo starts at 4/17229290
2024-04-19 10:41:34 +06 [2464031-4]  LOG:  consistent recovery state reached at 4/180BE290
2024-04-19 10:41:34 +06 [2464031-5]  LOG:  invalid record length at 4/180BE290: wanted 24, got 0
2024-04-19 10:41:34 +06 [2464034-1]  LOG:  started streaming WAL from primary at 4/18000000 on timeline 3
2024-04-19 10:41:34 +06 [2464037-1] [local] postgres@postgres FATAL:  the database system is starting up
2024-04-19 10:41:34 +06 [2464040-1] [local] postgres@postgres FATAL:  the database system is starting up
2024-04-19 10:41:34 +06 [2464045-1] [local] postgres@postgres FATAL:  the database system is starting up
2024-04-19 10:41:34 +06 [2464047-1] [local] postgres@postgres FATAL:  the database system is starting up
2024-04-19 10:41:35 +06 [2464049-1] [local] postgres@postgres FATAL:  the database system is starting up
2024-04-19 10:41:35 +06 [2464055-1] [local] postgres@postgres FATAL:  the database system is starting up
2024-04-19 10:41:35 +06 [2464056-1] [local] postgres@postgres FATAL:  the database system is starting up
2024-04-19 10:41:36 +06 [2464058-1] [local] postgres@postgres FATAL:  the database system is starting up

Have you tried to use GitHub issue search?

Anything else we need to know?

No response

CyberDem0n commented 6 months ago

After restoring basebackup standby node needs to replay plenty of WAL files before it could start accepting client connections. This is not Patroni problem. For the future please use Slack for questions.