[分享] FATAL: requested timeline 37 does not contain minimum recovery point 0/4E018BA0 on timeline 36

在Patroni集群正常运行时,手动强制提升某个备节点(即replica节点)为主节点时,存在一定概率引发备节点不能正常启动的问题。

现象:

  • Patroni日志
2021-06-24 10:23:37 +0800 INFO: Lock owner: pgsql-03-standby; I am pgsql-01-standby
2021-06-24 10:23:37 +0800 INFO: does not have lock
2021-06-24 10:23:37 +0800 INFO: establishing a new patroni connection to the postgres cluster
2021-06-24 10:23:37 +0800 INFO: Local timeline=37 lsn=0/4E000348
2021-06-24 10:23:37 +0800 INFO: master_timeline=36
2021-06-24 10:23:37 +0800 INFO: Register service pg-cluster-standby, params {'service_id': 'pg-cluster-standby/pgsql-01-standby', 'address': '10.37.129.6', 'port': 5432, 'check': {'http': 'http://10.37.129.6:8008/replica', 'interval': '15s', 'DeregisterCriticalServiceAfter': '150.0s'}, 'tags': ['pg-cluster-consul-standby', 'replica']}
2021-06-24 10:23:37 +0800 INFO: running pg_rewind from pgsql-03-standby
2021-06-24 10:23:37 +0800 INFO: running pg_rewind from dbname=postgres user=rewind-user host=10.37.129.8 port=5432
2021-06-24 10:23:38 +0800 INFO: pg_rewind exit code=0
2021-06-24 10:23:38 +0800 INFO:  stdout=
2021-06-24 10:23:38 +0800 INFO:  stderr=pg_rewind: servers diverged at WAL location 0/4E000268 on timeline 36
pg_rewind: rewinding from last common checkpoint at 0/4E0001B8 on timeline 36
pg_rewind: Done!

2021-06-24 10:23:38 +0800 WARNING: Postgresql is not running.
2021-06-24 10:23:38 +0800 INFO: Lock owner: pgsql-03-standby; I am pgsql-01-standby
2021-06-24 10:23:38 +0800 INFO: pg_controldata:
  • 数据库日志
2021-06-24 10:29:02.028 CST [2211] LOG:  database system was interrupted while in recovery at log time 2021-06-24 10:22:45 CST
2021-06-24 10:29:02.028 CST [2211] HINT:  If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.
2021-06-24 10:29:02.030 CST [2212] FATAL:  the database system is starting up
2021-06-24 10:29:02.036 CST [2214] FATAL:  the database system is starting up
2021-06-24 10:29:02.145 CST [2211] LOG:  restored log file "00000025.history" from archive
cp: cannot stat ‘../wal_archive/00000026.history’: No such file or directory
2021-06-24 10:29:02.148 CST [2211] LOG:  entering standby mode
2021-06-24 10:29:02.150 CST [2211] LOG:  restored log file "00000025.history" from archive
cp: cannot stat ‘../wal_archive/00000025000000000000004E’: No such file or directory
cp: cannot stat ‘../wal_archive/00000024000000000000004E’: No such file or directory
2021-06-24 10:29:02.156 CST [2211] FATAL:  requested timeline 37 does not contain minimum recovery point 0/4E018BA0 on timeline 36
2021-06-24 10:29:02.157 CST [2208] LOG:  startup process (PID 2211) exited with exit code 1
2021-06-24 10:29:02.157 CST [2208] LOG:  aborting startup due to startup process failure
2021-06-24 10:29:02.158 CST [2208] LOG:  database system is shut down

原因:

  1. 数据库每次恢复会依赖一个名为<timeline>.history的文件,此文件存放在
    数据库PGDATA/pg_wal以及wal文件归档目录下,文件中记录数据库基于timeline恢复时初始检查点的位置。
  2. 当我们手动升级备节点时,会导致timeline分化,当前状态会分化为新的timeline当Patroni检测到集群节点角色异常时,就会尝试使用pg_rewind(极狐GitLab内置的Patroni默认启用)转换手动升级的节点为备节点,但是pg_rewind在进行数据块比较时,目标数据库和源数据库需要处于相同的timeline,如果timeline不一致会导致转换失败。
    3.根据日志可以看到,当前节点timeline=37,主节点timeline=36
2021-06-24 10:23:37 +0800 INFO: Local timeline=37 lsn=0/4E000348
2021-06-24 10:23:37 +0800 INFO: master_timeline=36

因此后面执行pg_rewind时,提示出当前timeline已经从36分裂,出现了如下报错:

2021-06-24 10:23:38 +0800 INFO: pg_rewind exit code=0
2021-06-24 10:23:38 +0800 INFO:  stdout=
2021-06-24 10:23:38 +0800 INFO:  stderr=pg_rewind: servers diverged at WAL location 0/4E000268 on timeline 36

通过数据库日志也可以发现,rewind时基于timeline=37不能满足最小恢复需求

FATAL:  requested timeline 37 does not contain minimum recovery point 0/4E018BA0 on timeline 36

解决方案:
方案一(推荐):
如果数据库不是特别大的情况下,可以尝试设置如下参数:

patroni['remove_data_directory_on_rewind_failure'] = true
patroni['remove_data_directory_on_diverged_timelines'] = true

这两个参数作用是在pg_rewind失败时或者timeline发生分裂时清空PGDATA目录以重新初始化节点。

方案二:
删除PGDATA/pg_wal和wal归档目录下的history文件,删除后pg_rewind会尝试重新拉取history文件,history文件恢复后,Patroni会重新进行pg_rewind操作。