Почему могут падать потоковые реплики postgres?

Question

[wadomon]

Начали падать все, 10 штук, дружно позавчера, без каких-то видимых ранее причин, строго в определённое время сначала в 0 часов UTC, сегодня ровно в 0 часов EST

ОС ubuntu 16.04, версия PG 9.5 логи реплики

2019-04-13 00:00:03.370 EST [2267] LOG: 00000: invalid record length at 1BCA/DA0E0258 2019-04-13 00:00:03.370 EST [2267] LOCATION: ReadRecord, xlog.c:4012
2019-04-13 00:00:03.370 EST [14961] FATAL: 57P01: terminating walreceiver process due to administrator command 2019-04-13 00:00:03.370 EST [14961] LOCATION: ProcessWalRcvInterrupts, walreceiver.c:167
2019-04-13 00:00:03.370 EST [2267] LOG: 00000: invalid record length at 1BCA/DA0E0258
2019-04-13 00:00:03.370 EST [2267] LOCATION: ReadRecord, xlog.c:4012
2019-04-13 00:00:03.370 EST [2267] LOG: 00000: invalid record length at 1BCA/DA0E0258
2019-04-13 00:00:03.370 EST [2267] LOCATION: ReadRecord, xlog.c:4012
2019-04-13 00:00:03.370 EST [2267] LOG: 00000: invalid record length at 1BCA/DA0E0258
2019-04-13 00:00:03.370 EST [2267] LOCATION: ReadRecord, xlog.c:4012

А на мастере в это время - ничего, вообще!

2019-04-12 23:59:49.854 EST [49236] tracker@aaa LOG: 08006: could not receive data from client: Connection reset by peer

2019-04-12 23:59:49.854 EST [49236] tracker@aaa LOCATION: pq_recvbuf, pqcomm.c:919

2019-04-13 00:00:09.589 EST [49559] tracker@aaa LOG: 08006: could not receive data from client: Connection reset by peer

2019-04-13 00:00:09.589 EST [49559] tracker@aaa LOCATION: pq_recvbuf, pqcomm.c:919

2019-04-13 00:00:09.589 EST [49561] tracker@aaa LOG: 08006: could not receive data from client: Connection reset by peer

2019-04-13 00:00:09.589 EST [49561] tracker@aaa LOCATION: pq_recvbuf, pqcomm.c:919

2019-04-13 00:00:09.589 EST [49556] tracker@aaa LOG: 08006: could not receive data from client: Connection reset by peer

сейчас восстановил 2 реплики из 10ти, жду 0 часов по ЕСТ

postgres=# select * from pg_stat_replication;

pid | usesysid | usename | application_name | client_addr | client_hostname | client_port | backend_start | backend_xmin | state | sent_location | write_location | flush_location | replay_location | sync_priority | sync_state -------+----------+----------+------------------+----------------+-----------------+-------------+-------------------------------+--------------+-----------+---------------+----------------+----------------+-----------------+---------------+------------

92078 | 10 | postgres | walreceiver | 18.72.2.14 | | 2184 | 2019-04-13 05:59:55.361197-05 | | streaming | 1BD6/63740D68 | 1BD6/63740D68 | 1BD6/63740D68 | 1BD6/6373DE78 | 0 | async

91982 | 10 | postgres | walreceiver | 31.22.2.8 | | 31620 | 2019-04-13 05:59:38.198516-05 | 486133549 | streaming | 1BD6/63740D68 | 1BD6/63740D68 | 1BD6/63740D68 | 1BD6/6373DE78 | 0 | async

(2 rows)

Comments

[Melkij]

Что выше по логу? Что далее по логу? walreceiver из списка процессов пропал или остался висеть?

[wadomon]

По логу мастера? Ничего ровным счётом. Да и по логу реплик всё тоже самое, нет wal больше не висит

1:~# ps ax|grep wal
14877 pts/0 S+ 0:00 grep --color=auto wal

замирает вот на этом

1:~# ps ax|grep postg
12035 ? S 0:07 /usr/lib/postgresql/9.5/bin/postgres -D /var/lib/postgresql/9.5/main -c config_file=/etc/postgresql/9.5/main/postgresql.conf
12036 ? Ss 3:39 postgres: 9.5/main: startup process recovering 0000000100001BCA000000DA
12045 ? Ss 1:01 postgres: 9.5/main: checkpointer process
12046 ? Ss 0:02 postgres: 9.5/main: writer process
12944 ? Ss 0:03 postgres: 9.5/main: stats collector process
12950 ? Ss 0:11 postgres: 9.5/main: postgres postgres 127.0.0.1(46338) idle
15039 pts/0 S+ 0:00 grep --color=auto postg

Разумеется, никакие рестарты не помогают, только полная переливка.

[Melkij]

Проблемный сегмент по md5 идентичен тому что на мастере? Это последний WAL на репликах или они загружали WAL дальше?
Раз при рестарте поведение сохраняется - прикрепите лог с log_min_messages=debug5 , с десяток строк от pg_xlogdump --start=1BCA/DA0E0258
Ну и продублирую вопрос с ruSO - какая точно версия СУБД?

не скажу что впервые вижу схожую проблему, однажды мы уже ловили похожую проблему. У нас, впрочем, проблему спровоцировало плановое переключение мастера, но емнип ничего полезного раскопать не смогли. Поэтому особо интересно, что у вас с базой делается в полночь. У postgresql нет синхронизации своей активности с часами, поэтому триггер наверняка внешний.

[wadomon]

Мм, нет, сегмент DA по md5 бьются как разные, а вот соседние одинаковые

мастер
postgres-1:~# md5sum /storage/pg_xlog/0000000100001BCA000000DA
3e0c659eff714861428f057f59e6366f /storage/pg_xlog/0000000100001BCA000000DA

один сдохший слейв
1:~# md5sum /var/lib/postgresql/9.5/main/pg_xlog/0000000100001BCA000000DA
42d0198d9d54b28529ba04907956729f /var/lib/postgresql/9.5/main/pg_xlog/0000000100001BCA000000DA

/usr/lib/postgresql/9.5/bin/pg_xlogdump --start=1BCA/DA0E0258
pg_xlogdump: FATAL: could not find a valid record after 1BCA/DA0E0258
видимо уже нет

ну да, wal сдыхает и дальше не двигается, реплика померла.
Лог в дебагом вести 100 мб

52.14.78.85/qq.log

[Melkij]

Интересно, что реплика судя по логу пытается перекачать 1BCA/DA000000 с апстрима, но её старательно убивают. 192.168.10.10 - мастер? Или каскад? Рядом с 2019-04-13 15:22:54.761 на 192.168.10.10 ничего в логах не осталось?

на мастере pg_xlogdump тоже говорит что не может распарсить? А если ему указать явно путь до сегмента?

[wadomon]

10.10 да, это мастер, у хостера сетка внутренняя

2019-04-13 15:22:54 - такого времени ещё нет, это же EST, сейчас там 12 только наступило
Если время 15-7, то это 8, есть рядом такая запись возможно любопытная.
И таких записей - ну довольно прилично

2019-04-13 10:47:38.334 EST [10121] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 10:51:06.645 EST [11749] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 10:54:47.019 EST [12950] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 10:57:10.068 EST [13945] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 10:59:34.017 EST [14668] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 11:02:54.328 EST [16177] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 11:13:34.900 EST [20508] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 11:28:13.727 EST [26485] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 11:30:11.725 EST [27348] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 11:34:26.986 EST [28815] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 11:35:19.129 EST [29301] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 11:41:21.386 EST [31630] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 11:42:14.747 EST [31888] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 11:49:20.204 EST [34554] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 11:51:48.013 EST [35694] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 11:54:47.104 EST [36703] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 12:05:33.801 EST [41517] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 12:08:27.831 EST [42435] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 12:08:44.030 EST [42502] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed

2019-04-13 08:21:09.926 EST [50291] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed
2019-04-13 08:21:09.926 EST [50291] postgres@[unknown] LOCATION: XLogRead, walsender.c:2148

но вокруг неё такая же унылая фигня
2019-04-13 08:21:05.204 EST [50231] tracker@aaa LOG: 08006: could not receive data from client: Connection reset by peer

pg_xlogdump я и пробовал на мастере
а явно как указать? тут же не путь до файла вроде.....1BCA/DA000000
нахожусь в каталоге с бинлогами
/storage/pg_xlog# /usr/lib/postgresql/9.5/bin/pg_xlogdump --start=1BCA/DA0E0258
pg_xlogdump: FATAL: could not find a valid record after 1BCA/DA0E0258

а на слейве оно давно потёрто....

[Melkij]

2019-04-13 15:22:54 - такого времени ещё нет, это же EST, сейчас там 12 только наступило

Я имел в виду эквивалент для 2019-04-13 15:22:54 UTC. Очень уж интересный ход:

2019-04-13 15:22:54.761 UTC [2770] LOG: started streaming WAL from primary at 1BCA/DA000000 on timeline 1
2019-04-13 15:22:54.761 UTC [2770] DEBUG: sending write 1BCA/D9FFFFB0 flush 1BCA/D9FFFFB0 apply 1BCA/D9FFFFB0
2019-04-13 15:22:54.761 UTC [2770] DEBUG: sending hot standby feedback xmin 0 epoch 0
2019-04-13 15:22:54.762 UTC [2770] DEBUG: sendtime 2019-04-13 15:22:54.765466+00 receipttime 2019-04-13 15:22:54.762726+00 replication apply delay (N/A) transfer latency 0 ms
2019-04-13 15:22:54.762 UTC [2770] DEBUG: sending write 1BCA/DA020000 flush 1BCA/D9FFFFB0 apply 1BCA/D9FFFFB0
2019-04-13 15:22:54.815 UTC [2770] DEBUG: sending write 1BCA/DA020000 flush 1BCA/DA020000 apply 1BCA/D9FFFFB0
2019-04-13 15:22:54.816 UTC [2770] FATAL: terminating walreceiver process due to administrator command

walreceiver запустился, отчитался апстриму что сохранил 1BCA/DA020000, а вот дальше его кто-то прибил.

2019-04-13 10:47:38.334 EST [10121] postgres@[unknown] ERROR: 58P01: requested WAL segment 0000000100001B93000000B7 has already been removed

Это уже какое-то время назад дохлая реплика пытается подцепиться, база отвечает "прости, такого старья не храню". Стоит добавить %h в log_line_prefix, тогда хоть будет понятно с какого адреса.

а явно как указать? тут же не путь до файла вроде.....1BCA/DA000000

это позиция wal, но оно довольно просто отражается в имя файла: 0000000100001BCA000000DA. timeline id да два 32-битных числа в HEX

[wadomon]

%h это на реплике добавить? добавил, пока что на реплике дохлой вот что

2019-04-13 12:47:18.369 EST [32707] LOG: database system was shut down in recovery at 2019-04-13 12:47:16 EST
2019-04-13 12:47:18.369 EST [32707] LOG: entering standby mode
[local] 2019-04-13 12:47:18.424 EST [32708] [unknown]@[unknown] LOG: incomplete startup packet
2019-04-13 12:47:18.427 EST [32707] LOG: redo starts at 1BCA/B39678F0
2019-04-13 12:47:18.908 EST [32707] LOG: consistent recovery state reached at 1BCA/C70768B8
2019-04-13 12:47:18.908 EST [32706] LOG: database system is ready to accept read only connections
2019-04-13 12:47:19.618 EST [32718] LOG: started streaming WAL from primary at 1BCA/DA000000 on timeline 1
2019-04-13 12:47:19.671 EST [32718] FATAL: terminating walreceiver process due to administrator command

Кто может даже в теории прибивать? И куда дальше ковырять?

[Melkij]

%h - это чтобы найти, кто пытается тянуть сегмент "requested WAL segment 0000000100001B93000000B7 has already been removed" с того хоста, где эта ошибка в логах появлется. Непосредственно к вопросу не относится, это штатная картина для отставшей реплики со вполне очевидной картиной в логах этой реплики и бесконечного цикла старта репликации и получения ошибки что сегмент предоставить апстрим не может.

А убивать walreceiver... Может фактически кто угодно, walreceiver можно делать kill и отреагирует в лог он именно так. Вот только при standby_mode=on как у вас он должен проверить restore_command и поскольку той нет - перезапускаться через wal_retrieve_retry_interval. Сколько он, кстати?

Точная версия базы-то такая? Ещё раз спрошу. 9.5.16?
И с чего начинали- "invalid record length at 1BCA/DA0E0258" при рестарте не повторяется?

[wadomon]

Странно, куда-то делся мой ответ, ну ладно.
wal_retrieve_retry_interval дефолтный, 5с

В общем стало ещё хуже - оставшиеся 2 реплики не упали в 7 утра мск (0 по ест). Я вообще перестал что-то понимать. Если рестартнуть рабочую репку, то

2019-04-14 02:51:54.246 EST [62912] LOG: 00000: received fast shutdown request
2019-04-14 02:51:54.246 EST [62912] LOCATION: pmdie, postmaster.c:2659
2019-04-14 02:51:54.246 EST [62912] LOG: 00000: aborting any active transactions
2019-04-14 02:51:54.246 EST [62912] LOCATION: pmdie, postmaster.c:2685
2019-04-14 02:51:54.246 EST [62982] FATAL: 57P01: terminating walreceiver process due to administrator command
2019-04-14 02:51:54.246 EST [62982] LOCATION: ProcessWalRcvInterrupts, walreceiver.c:167
2019-04-14 02:51:54.246 EST [62983] postgres@postgres FATAL: 57P01: terminating connection due to administrator command
2019-04-14 02:51:54.246 EST [62983] postgres@postgres LOCATION: ProcessInterrupts, postgres.c:2915
2019-04-14 02:51:54.246 EST [62984] postgres@postgres FATAL: 57P01: terminating connection due to administrator command
2019-04-14 02:51:54.246 EST [62984] postgres@postgres LOCATION: ProcessInterrupts, postgres.c:2915
2019-04-14 02:51:55.704 EST [62914] LOG: 00000: shutting down
2019-04-14 02:51:55.704 EST [62914] LOCATION: ShutdownXLOG, xlog.c:8038
2019-04-14 02:51:55.712 EST [62914] LOG: 00000: database system is shut down
2019-04-14 02:51:55.712 EST [62914] LOCATION: ShutdownXLOG, xlog.c:8073
2019-04-14 02:51:56.483 EST [79125] LOG: 00000: database system was shut down in recovery at 2019-04-14 02:51:55 EST
2019-04-14 02:51:56.483 EST [79125] LOCATION: StartupXLOG, xlog.c:6012
2019-04-14 02:51:56.483 EST [79125] LOG: 00000: entering standby mode
2019-04-14 02:51:56.483 EST [79125] LOCATION: StartupXLOG, xlog.c:6087
2019-04-14 02:51:56.587 EST [79125] LOG: 00000: redo starts at 1BFB/4A2951C8
2019-04-14 02:51:56.587 EST [79125] LOCATION: StartupXLOG, xlog.c:6785
2019-04-14 02:51:56.818 EST [79128] [unknown]@[unknown] LOG: 08P01: incomplete startup packet
2019-04-14 02:51:56.818 EST [79128] [unknown]@[unknown] LOCATION: ProcessStartupPacket, postmaster.c:1914
2019-04-14 02:51:57.323 EST [79133] postgres@postgres FATAL: 57P03: the database system is starting up
2019-04-14 02:51:57.323 EST [79133] postgres@postgres LOCATION: ProcessStartupPacket, postmaster.c:2204
2019-04-14 02:51:57.465 EST [79125] LOG: 00000: consistent recovery state reached at 1BFB/6E9C7840
2019-04-14 02:51:57.465 EST [79125] LOCATION: CheckRecoveryConsistency, xlog.c:7588
2019-04-14 02:51:57.465 EST [79125] LOG: 00000: invalid record length at 1BFB/6E9C7840
2019-04-14 02:51:57.465 EST [79125] LOCATION: ReadRecord, xlog.c:4012
2019-04-14 02:51:57.465 EST [79124] LOG: 00000: database system is ready to accept read only connections
2019-04-14 02:51:57.465 EST [79124] LOCATION: sigusr1_handler, postmaster.c:4991
2019-04-14 02:51:57.495 EST [79135] LOG: 00000: started streaming WAL from primary at 1BFB/6E000000 on timeline 1
2019-04-14 02:51:57.495 EST [79135] LOCATION: WalReceiverMain, walreceiver.c:363

всё, репка встала
-2:~# ps ax|grep wal
79135 ? Ss 0:08 postgres: 9.5/main: wal receiver process streaming 1BFB/94130158

Может ли что угодно среди других репок хоть каким-то образом влиять на эти падения? Вопрос бредовый какой-то....