pg_probackup icon indicating copy to clipboard operation
pg_probackup copied to clipboard
verified publisher icon postgrespro

pg_probackup 2.4.10: Problem in receivexlog

Open ykurenkov opened this issue 4 years ago • 58 comments

CentOS 7, PostgreSQL 11.11. Бэкап производится мастера локально на NFS ресурс.

2021-03-15 03:28:47 +05 [26447]: INFO: Progress: (11936/12316). Process file "base/34749178/34749245.584"
2021-03-15 03:29:04 +05 [26447]: INFO: Progress: (11937/12316). Process file "base/34749178/34749245.583"
2021-03-15 03:31:20 +05 [26447]: ERROR: Problem in receivexlog
2021-03-15 03:31:20 +05 [26447]: ERROR: interrupted during backup
2021-03-15 03:31:20 +05 [26447]: ERROR: Data files transferring failed, time elapsed: 4h:31m
2021-03-15 03:31:20 +05 [26447]: WARNING: backup in progress, stop backup
2021-03-15 03:31:20 +05 [26447]: WARNING: Backup QPZ0O2 is running, setting its status to ERROR

ykurenkov avatar Mar 15 '21 07:03 ykurenkov

Добрый день! Можете показать постгресовые логи на этот момент времени?

gsmolk avatar Mar 15 '21 09:03 gsmolk 

INFO: pg_probackup archive-push completed successfully, pushed: 1, skipped: 0, time elapsed: 1m:59s
INFO: pg_probackup archive-push WAL file: 000000010000028B000000E6, threads: 1/1, batch: 1/1, compression: none
LOG: pushing file "000000010000028B000000E6"
VERBOSE: Temp WAL file successfully created: "/var/lib/pgsql/11/backups/wal/ny1-11/000000010000028B000000E6.part"
2021-03-15 03:31:20 +05 postgres postgres@[local] PID:26450 LOG:  could not send data to client: Broken pipe
2021-03-15 03:31:20 +05 postgres postgres@[local] PID:26450 FATAL:  connection to client lost
VERBOSE: Rename "/var/lib/pgsql/11/backups/wal/ny1-11/000000010000028B000000E6.part" to "/var/lib/pgsql/11/backups/wal/ny1-11/000000010000028B000000E6"
INFO: pg_probackup archive-push completed successfully, pushed: 1, skipped: 0, time elapsed: 1s:315ms

ykurenkov avatar Mar 15 '21 10:03 ykurenkov

Похоже что дело в этом:

2021-03-15 03:31:20 +05 postgres postgres@[local] PID:26450 LOG:  could not send data to client: Broken pipe
2021-03-15 03:31:20 +05 postgres postgres@[local] PID:26450 FATAL:  connection to client lost

Какие-то сетевые проблемы.

gsmolk avatar Mar 15 '21 11:03 gsmolk

Это локальный бэкап - сервер и pg_probackup на одном хосте.

ykurenkov avatar Mar 15 '21 11:03 ykurenkov

Хм, странно

gsmolk avatar Mar 15 '21 11:03 gsmolk

Перенес бэкапы с мастера на стендбай. Тут же случилось не понятное.

2021-03-19 23:50:06 +05 [13251]: INFO: Progress: (12558/12561). Process file "base/23140623/23820768.60"
2021-03-19 23:50:08 +05 [13251]: INFO: Progress: (12559/12561). Process file "base/34749178/34749245.165"
2021-03-19 23:50:09 +05 [13251]: INFO: Progress: (12560/12561). Process file "base/23140623/23820768.61"
2021-03-19 23:50:11 +05 [13251]: INFO: Progress: (12561/12561). Process file "base/23140623/23820768.62"
2021-03-19 23:50:13 +05 [13251]: INFO: Data files are transferred, time elapsed: 50m:8s
2021-03-19 23:50:14 +05 [13251]: INFO: wait for pg_stop_backup()
2021-03-19 23:50:14 +05 [13251]: INFO: pg_stop backup() successfully executed
2021-03-19 23:50:15 +05 [13251]: INFO: Wait for LSN 2A6/F0CCC08 in streamed WAL segment /var/lib/pgsql/11/backups/backups/ny1-11/QQ8A01/database/pg_wal/00000001000002A60000000F
2021-03-20 00:00:15 +05 [13251]: ERROR: WAL segment 00000001000002A60000000F could not be streamed in 600 seconds
2021-03-20 00:00:15 +05 [13251]: WARNING: Backup QQ8A01 is running, setting its status to ERROR

Хотелось бы понять причину нестабильности. Предыдущие дни после создания этого issue все на мастере бэкапилось без приключений. На всякий случай: image Включено принодительное зарытие WAL'ов.

ykurenkov avatar Mar 20 '21 08:03 ykurenkov

Нужен выхлоп уровня VERBOSE

gsmolk avatar Mar 20 '21 10:03 gsmolk

Повторный запуск на standby:

INFO: Progress: (12561/12563). Process file "base/34749178/34749245.345"
INFO: Progress: (12562/12563). Process file "base/23140623/23820768.31"
INFO: Progress: (12563/12563). Process file "base/34749178/34749245.346"
INFO: Data files are transferred, time elapsed: 48m:5s
INFO: wait for pg_stop_backup()
INFO: pg_stop backup() successfully executed
INFO: Wait for LSN 2A8/7C9FA70 in streamed WAL segment /var/lib/pgsql/11/backups/backups/ny1-11/QQ9EDG/database/pg_wal/00000001000002A800000007
ERROR: WAL segment 00000001000002A800000007 could not be streamed in 600 seconds
WARNING: Backup QQ9EDG is running, setting its status to ERROR

ykurenkov avatar Mar 20 '21 11:03 ykurenkov

Все ещё нужен verbose:--log-level-console=verbose

gsmolk avatar Mar 20 '21 11:03 gsmolk

Это локальный бэкап - сервер и pg_probackup на одном хосте

Файрволл?

gsmolk avatar Mar 20 '21 11:03 gsmolk

Это локальный бэкап - сервер и pg_probackup на одном хосте

Файрволл?

Это мастер image и стендбай image

ykurenkov avatar Mar 20 '21 12:03 ykurenkov 


VERBOSE: Skipping blknum 131067 in file: "/var/lib/pgsql/11/data/base/34749178/34749245.435"
VERBOSE: Skipping blknum 131068 in file: "/var/lib/pgsql/11/data/base/34749178/34749245.435"
VERBOSE: Skipping blknum 131069 in file: "/var/lib/pgsql/11/data/base/34749178/34749245.435"
VERBOSE: Skipping blknum 131070 in file: "/var/lib/pgsql/11/data/base/34749178/34749245.435"
VERBOSE: Skipping blknum 131071 in file: "/var/lib/pgsql/11/data/base/34749178/34749245.435"
VERBOSE: Skipping the unchanged file: "/var/lib/pgsql/11/data/base/34749178/34749245.435"
INFO: Data files are transferred, time elapsed: 1h:40m
VERBOSE: (query) SET client_min_messages = warning;
VERBOSE: (query) SET datestyle = 'ISO, DMY';
VERBOSE: (query) SELECT pg_catalog.txid_snapshot_xmax(pg_catalog.txid_current_snapshot()), current_timestamp(0)::timestamptz, pg_catalog.pg_last_wal_replay_lsn(), labelfile, spcmapfile FROM pg_catalog.pg_stop_backup(false, false)
INFO: wait for pg_stop_backup()
INFO: pg_stop backup() successfully executed
LOG: stop_lsn: 2AC/F761BD0
LOG: Looking for LSN 2AC/F761BD0 in segment: 00000001000002AC0000000F
INFO: Wait for LSN 2AC/F761BD0 in streamed WAL segment /var/lib/pgsql/11/backups/backups/ny1-11/QQAA9R/database/pg_wal/00000001000002AC0000000F
ERROR: WAL segment 00000001000002AC0000000F could not be streamed in 600 seconds
WARNING: Backup QQAA9R is running, setting its status to ERROR

ykurenkov avatar Mar 21 '21 07:03 ykurenkov

А можете показать метаданные этого бэкапа и содержимое его директории pg_wal?

gsmolk avatar Mar 21 '21 08:03 gsmolk

У меня есть подозрение, что мы тут просто не уложились в 600 секунд застримить все нужные сегменты.

gsmolk avatar Mar 21 '21 11:03 gsmolk

А можете показать метаданные этого бэкапа и содержимое его директории pg_wal?

backup.control:

#Configuration
backup-mode = DELTA
stream = true
compress-alg = none
compress-level = 1
from-replica = true

#Compatibility
block-size = 8192
xlog-block-size = 8192
checksum-version = 1
program-version = 2.4.10
server-version = 11

#Result backup info
timelineid = 1
start-lsn = 2AB/926B69A8
stop-lsn = 0/0
start-time = '2021-03-20 20:01:03+00'
end-time = '2021-03-20 21:51:14+00'
recovery-xid = 0
data-bytes = 11419487205
wal-bytes = 0
uncompressed-bytes = 11408696325
pgdata-bytes = 1333884927587
status = ERROR
parent-backup-id = 'QQ9N58'
primary_conninfo = 'user=postgres port=5433 sslmode=prefer sslcompression=0 krbsrvname=postgres target_session_attrs=any'
content-crc = 1944811207

pg_wal пустой.

У меня есть подозрение, что мы тут просто не уложились в 600 секунд застримить все нужные сегменты.

Локальный бэкап на standby, с которым никто кроме pg_probackup не работает. Что ему могло помешать? До этого мастер бэкапился без проблем.

Сейчас картина выглядит следующим образом:

=============================================================================================================================================
 Instance  Version  ID      Recovery Time           Mode   WAL Mode  TLI    Time    Data     WAL  Zratio  Start LSN     Stop LSN      Status 
=============================================================================================================================================
 ny1-11    11       QQB5E6  2021-03-21 13:54:33+05  DELTA  STREAM    1/1  1h:41m    21GB  2112MB    1.00  2AE/A79017F8  2AF/2AF720F8  OK     
 ny1-11    11       QQAA9R  ----                    DELTA  STREAM    1/1  1h:50m    11GB       0    1.00  2AB/926B69A8  0/0           ERROR  
 ny1-11    11       QQA4O1  ----                    DELTA  STREAM    1/1  1h:10m  8675MB       0    1.00  2AA/E47A1B50  0/0           ERROR  
 ny1-11    11       QQ9N58  2021-03-20 18:03:42+05  DELTA  STREAM    1/1  1h:22m    11GB  1136MB    1.00  2A8/BC02F700  2A9/15429F8   OK     
 ny1-11    11       QQ9EDG  ----                    DELTA  STREAM    1/1  58m:9s  7937MB       0    1.00  2A7/CDA26598  0/0           ERROR  
 ny1-11    11       QQ8A01  ----                    DELTA  STREAM    1/1   1h:0m  5135MB       0    1.00  2A5/F90D6C48  0/0           ERROR  
 ny1-11    11       QQ6FC2  2021-03-19 00:08:41+05  DELTA  STREAM    1/1   1h:8m  4240MB   576MB    1.00  2A2/F5000028  2A3/170F53D0  OK     
 ny1-11    11       QQ4KO1  2021-03-18 00:09:50+05  DELTA  STREAM    1/1   1h:9m  6215MB   464MB    1.00  2A0/26000028  2A0/411F3A38  OK     
 ny1-11    11       QQ2Q01  2021-03-17 00:07:57+05  DELTA  STREAM    1/1   1h:7m  3079MB   464MB    1.00  29C/DF000028  29C/FA010580  OK     
 ny1-11    11       QQ1YAE  2021-03-16 14:12:43+05  DELTA  STREAM    1/1  1h:11m  7176MB  1584MB    1.00  29B/71000110  29B/D206DA98  OK     
 ny1-11    11       QQ00X6  2021-03-15 18:19:11+05  FULL   STREAM    1/0  6h:16m  1208GB  3616MB    1.00  297/F0002698  298/D0E5BA18  OK     
 ny1-11    11       QPX602  2021-03-14 02:21:50+05  DELTA  STREAM    1/1  3h:21m   225GB    29GB    1.00  24B/C102AA00  253/6DF7EF8   OK     
 ny1-11    11       QPVBC2  2021-03-13 00:39:08+05  DELTA  STREAM    1/1  1h:39m   126GB    14GB    1.00  215/89211CD8  219/19361F50  OK     
 ny1-11    11       QPUDIE  2021-03-12 12:47:03+05  DELTA  STREAM    1/1  1h:57m   181GB    18GB    1.00  1F8/4D01C6B8  1FC/AC349598  OK     
 ny1-11    11       QPSWYS  2021-03-11 21:52:18+05  FULL   STREAM    1/0  5h:58m  1196GB    55GB    1.00  1CC/F7739488  1DA/9D46FA68  OK

Все до QQ6FC2 включительно и QQ9N58 были сделаны на мастере.

ykurenkov avatar Mar 21 '21 17:03 ykurenkov

Заметил у себя в скрипте бэкапа ошибку: при локальном бэкапе на standby pg_probackup получал параметр -h с адресом мастера.

ykurenkov avatar Mar 21 '21 18:03 ykurenkov

pg_wal пустой.

Вот это номер.

Заметил у себя в скрипте бэкапа ошибку: при локальном бэкапе на standby pg_probackup получал параметр -h с адресом мастера.

Очень странные симптомы, если стриминг не может ничего застримить (например, мастер уже отротировал нужный сегмент), то мы должны были упасть с ошибкой. Если не отротировал, то хоть что-то должно было быть застримлено.

gsmolk avatar Mar 21 '21 21:03 gsmolk

https://github.com/postgrespro/pg_probackup/issues/346#issuecomment-803524016 А полного лога от этого примера не осталось? Можете им поделиться?

gsmolk avatar Mar 21 '21 21:03 gsmolk

при локальном бэкапе на standby pg_probackup получал параметр -h с адресом мастера.

Это, кстати, серьезная проблема - можно получить неконсистентный бэкап и эту неконсистентность не факт, что получится обнаружить. Хорошо, что бэкап зафейлился (я, правда, пока не понимаю почему). Надо подумать о том, как от этого защищать юзера. Как минимум можно попробовать проверять, что состояние инстанса с точки зрения pg_control и c точки зрения libpq коннекта идентичные.

gsmolk avatar Mar 21 '21 22:03 gsmolk

#346 (comment) А полного лога от этого примера не осталось? Можете им поделиться?

https://cloud.oblteh.ru/s/XfGKQgSt8sifq6Z

ykurenkov avatar Mar 22 '21 05:03 ykurenkov

Заметил у себя в скрипте бэкапа ошибку: при локальном бэкапе на standby pg_probackup получал параметр -h с адресом мастера

После исправления скрипта бэкап QQBZC1 все равно завершился ошибкой. Полный лог в том же файле. image

ykurenkov avatar Mar 22 '21 06:03 ykurenkov

Вижу как минимум одну проблему:

2021-03-21 01:01:05 +05 [15428]: LOG: started streaming WAL at 2AB/92000000 (timeline 1)
2021-03-21 01:01:05 +05 [15428]: ERROR: Problem in receivexlog
2021-03-21 01:01:05 +05 [15428]: VERBOSE: Excluding directory content: base/pgsql_tmp
...

Несмотря на явную ошибку, бэкап продолжил выполняться. Это залет

gsmolk avatar Mar 22 '21 11:03 gsmolk

Как Вы смотрите на то, что я соберу Вам кастомный пакет с фиксом и мы посмотрим на новое поведение?

gsmolk avatar Mar 22 '21 14:03 gsmolk

Положительно.

ykurenkov avatar Mar 22 '21 15:03 ykurenkov

Пакеты в аттаче pbk-2.4.11.tar.gz

gsmolk avatar Mar 22 '21 17:03 gsmolk

Но этот фикс не решает эту проблему:

2021-03-22 02:16:39 +05 [17997]: ERROR: Problem in receivexlog
2021-03-22 02:16:40 +05 [17997]: ERROR: interrupted during backup
2021-03-22 02:16:40 +05 [17997]: ERROR: Data files transferring failed, time elapsed: 3h:16m
2021-03-22 02:16:40 +05 [17997]: WARNING: backup in progress, stop backup
2021-03-22 02:16:40 +05 [17997]: VERBOSE: (query) SET client_min_messages = warning;
2021-03-22 02:16:40 +05 [17997]: VERBOSE: (query) SET datestyle = 'ISO, DMY';
2021-03-22 02:16:40 +05 [17997]: VERBOSE: (query) SELECT pg_catalog.txid_snapshot_xmax(pg_catalog.txid_current_snapshot()), current_timestamp(0)::timestamptz, pg_catalog.pg_last_wal_replay_lsn(), labelfile, spcmapfile FROM pg_catalog.pg_stop_backup(false, false)
2021-03-22 02:16:40 +05 [17997]: WARNING: Backup QQBZC1 is running, setting its status to ERROR

Опять же нужно посмотреть на лог постгреса в этот момент.

gsmolk avatar Mar 22 '21 18:03 gsmolk

Опять же нужно посмотреть на лог постгреса в этот момент.

2021-03-22 02:16:19 +05 [unknown] postgres@[local] PID:18000 LOG: terminating walsender process due to replication timeout 2021-03-22 02:16:40 +05 postgres postgres@[local] PID:17999 LOG: could not send data to client: Broken pipe 2021-03-22 02:16:40 +05 postgres postgres@[local] PID:17999 FATAL: connection to client lost

ykurenkov avatar Mar 23 '21 11:03 ykurenkov

Стоит попробовать увеличить wal_sender_timeout

gsmolk avatar Mar 23 '21 11:03 gsmolk

Сейчас в конфиге

wal_sender_timeout = 120s       # in milliseconds; 0 disables
wal_receiver_timeout = 120s             # time that receiver waits for

ykurenkov avatar Mar 23 '21 11:03 ykurenkov

Это сказывается #256? Это после него возникли эти строчки в конфигах.

ykurenkov avatar Mar 23 '21 11:03 ykurenkov