pg_probackup 2.4.10: Problem in receivexlog

[ykurenkov]

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

[gsmolk]

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

[ykurenkov]

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

[gsmolk]

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

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

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

[ykurenkov]

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

[gsmolk]

Хм, странно

[ykurenkov]

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

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 все на мастере бэкапилось без приключений. На всякий случай:

Включено принодительное зарытие WAL'ов.

[gsmolk]

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

[ykurenkov]

Повторный запуск на 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

[gsmolk]

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

[gsmolk]

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

Файрволл?

[ykurenkov]

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

Файрволл?

Это мастер

и стендбай

[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

[gsmolk]

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

[gsmolk]

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

[ykurenkov]

А можете показать метаданные этого бэкапа и содержимое его директории 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 были сделаны на мастере.