master_stop_timeout doesn't apply when waiting for user backends to close

[scottybrisbane]

Describe the bug For context, we are experiencing an issue where Postgres fast shutdown is getting stuck due to an issue where Citus background workers are getting stuck in a cancellation request and therefore not shutting down. This is due to an issue in PQCancel which is being fixed.

To mitigate this issue, we are trying to use the master_stop_timeout functionality in Patroni, but have found it doesn't work in this scenario. Postgres will remain in a shutting down state for far longer than the configured master_stop_timeout. This looks to be caused in part by 2 factors. The first is that the regex list of backend processes to exclude whilst waiting for backends to close does not include Citus Maintenance Daemon. The second is that the master_stop_timeout isn't applied when waiting for user backends to close.

Two possible solutions to this might be:

• Include Citus Maintenance Daemon in the regex of processes to exclude when waiting for user backends to close
• Apply the master_stop_timeout when waiting for user backends to close.

To Reproduce Trigger a situation where a not excluded backend process hangs and doesn't terminate on SIGTERM. Initiate a PostgreSQL fast shutdown (e.g. patronictl switchover). Notice that Postgres is stuck in a shutting down state. Wait for master_stop_timeout to expire. Postgres is not killed.

Expected behavior Given this situation, Postgres should be killed as per the functionality of master_stop_timeout.

Environment

• Patroni version: 2.1.4
• PostgreSQL version: 14.4
• DCS (and its version): Consul v1.10.2

Patroni configuration file

scope: citus-validate-00-work-2
namespace: /citus/citus-validate-00
name: citus-validate-00-work-2-a

restapi:
  listen: 0.0.0.0:8008
  connect_address: 10.0.209.154:8008
  authentication: <redacted>

consul:
  host: 127.0.0.1:8500
  token: <redacted>

bootstrap:
  dcs:
    check_timeline: true
    loop_wait: 10
    master_stop_timeout: 300
    maximum_lag_on_failover: 0
    retry_timeout: 10
    synchronous_mode: true
    ttl: 30
    postgresql:
      use_pg_rewind: false
      parameters:
        hot_standby: "on"
        max_connections: 8000
        max_prepared_transactions: 2000
        max_replication_slots: 10
        max_wal_senders: 10
        max_worker_processes: 16
        wal_keep_size: "6GB"
        wal_level: logical
        wal_log_hints: "on"

  initdb:
  - encoding: UTF8
  - data-checksums

  post_init: /usr/local/sbin/patroni-cluster-init.sh

postgresql:
  listen: 0.0.0.0:5432
  connect_address: 10.0.209.154:5432
  data_dir: /var/lib/postgresql/patroni/14
  bin_dir: /usr/lib/postgresql/14/bin
  pgpass: /var/lib/postgresql/.pgpass-patroni
  pg_hba: <redcated>
  authentication:
    replication: <redcated>
    superuser: <redcated>
    rewind: <redcated>
  parameters:
    archive_command: "pgbackrest --stanza=patroni archive-push %p"
    archive_mode: "on"
    autovacuum_analyze_scale_factor: 0.01
    autovacuum_vacuum_scale_factor: 0.01
    checkpoint_completion_target: 0.9
    citus.max_client_connections: 1000
    citus.shard_count: 24
    citus.stat_statements_track: all
    cron.database_name: "crondb"
    log_autovacuum_min_duration: 60000
    log_checkpoints: 'on'
    log_directory: '/var/log/postgresql'
    log_filename: 'postgresql.log'
    log_lock_waits: 'on'
    log_min_duration_statement: 10000
    log_min_error_statement: error
    log_min_messages: debug1
    log_rotation_age: 7d
    log_rotation_size: 100MB
    log_statement: ddl
    log_temp_files: 10MB
    logging_collector: 'on'
    maintenance_work_mem: "1000MB"
    max_slot_wal_keep_size: "6GB"
    max_wal_size: "16GB"
    min_wal_size: "4GB"
    password_encryption: 'scram-sha-256'
    random_page_cost: 1
    shared_buffers: "2309MB"
    shared_preload_libraries: "citus,pg_stat_statements,pg_cron,pg_partman_bgw,pglogical,pg_qualstats"
    ssl_cert_file: '/var/lib/postgresql/postgres.crt'
    ssl_key_file: '/var/lib/postgresql/postgres.key'
    ssl: 'on'
    synchronous_commit: "remote_write"
    unix_socket_directories: '/var/run/postgresql/'
    vacuum_cost_limit: 400
    work_mem: "32MB"
  recovery_conf:
    restore_command: "pgbackrest --stanza=patroni archive-get %f %p"
  callbacks:
    on_start: /usr/local/sbin/patroni-callback.py
    on_stop: /usr/local/sbin/patroni-callback.py
    on_role_change: /usr/local/sbin/patroni-callback.py
  create_replica_methods:
    - pgbackrest
    - basebackup
  pgbackrest:
    command: /usr/local/sbin/pgbackrest-restore.sh
    keep_data: True
    no_master: True
    no_params: True

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

patronictl show-config

check_timeline: true
loop_wait: 10
master_stop_timeout: 300
maximum_lag_on_failover: 0
postgresql:
  parameters:
    hot_standby: 'on'
    max_connections: 8000
    max_prepared_transactions: 2000
    max_replication_slots: 10
    max_wal_senders: 10
    max_worker_processes: 16
    wal_keep_size: 13GB
    wal_level: logical
    wal_log_hints: 'on'
  use_pg_rewind: false
retry_timeout: 10
synchronous_mode: true
ttl: 30

Have you checked Patroni logs?

Jul 21 03:11:02 citus-validate-00-work-2-a patroni[3501]: 2022-07-21 03:11:02,294 INFO: manual failover: demoting myself
Jul 21 03:11:02 citus-validate-00-work-2-a patroni[3501]: 2022-07-21 03:11:02,294 INFO: Demoting self (graceful)
Jul 21 03:11:02 citus-validate-00-work-2-a patroni[3501]: 2022-07-21 03:11:02,368 DEBUG: Waiting for user backends postgres: citus-validate-00-work-2: Citus Maintenance Daemon: 16386/10 , postgres: citus-validate-00-work-2: Citus Maintenance Daemon: 16388/10 , postgres: c
itus-validate-00-work-2: Citus Maintenance Daemon: 16389/10  to close
Jul 21 03:11:03 citus-validate-00-work-2-a patroni[3501]: 2022-07-21 03:11:03,263 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
Jul 21 03:11:03 citus-validate-00-work-2-a patroni[3501]: 2022-07-21 03:11:03,266 DEBUG: http://127.0.0.1:8500 "GET /v1/kv/citus/citus-validate-00/citus-validate-00-work-2/?recurse=1 HTTP/1.1" 200 None
Jul 21 03:11:03 citus-validate-00-work-2-a patroni[3501]: 2022-07-21 03:11:03,411 DEBUG: API thread: 10.0.213.183 - - "GET /primary HTTP/1.1" 200 - latency: 0.405 ms
Jul 21 03:11:04 citus-validate-00-work-2-a patroni[3501]: 2022-07-21 03:11:04,268 DEBUG: Converted retries value: 0 -> Retry(total=0, connect=None, read=None, redirect=0, status=None)
Jul 21 03:11:04 citus-validate-00-work-2-a patroni[3501]: 2022-07-21 03:11:04,271 DEBUG: http://127.0.0.1:8500 "GET /v1/kv/citus/citus-validate-00/citus-validate-00-work-2/?recurse=1 HTTP/1.1" 200 None

[CyberDem0n]

Well, yeah... We need to rethink the way of finding and identifying non-client backends...

[scottybrisbane]

@CyberDem0n Do you feel that thats the better fix here over applying the master_stop_timeout when waiting for user backends to close?