pg_probackup 2.4.10: Problem in receivexlog #346

ykurenkov · 2021-03-15T07:00:09Z

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

The text was updated successfully, but these errors were encountered:

gsmolk · 2021-03-15T09:27:22Z

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

ykurenkov · 2021-03-15T10:30:10Z

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-15T11:45:10Z

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

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 · 2021-03-15T11:48:42Z

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

gsmolk · 2021-03-15T11:55:33Z

Хм, странно

ykurenkov · 2021-03-20T08:41:30Z

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

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 · 2021-03-20T10:35:36Z

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

ykurenkov · 2021-03-20T11:40:11Z

Повторный запуск на 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 · 2021-03-20T11:43:13Z

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

gsmolk · 2021-03-20T11:44:26Z

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

Файрволл?

ykurenkov · 2021-03-20T12:13:27Z

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

Файрволл?

Это мастер

и стендбай

ykurenkov · 2021-03-21T07:10:58Z


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 · 2021-03-21T08:56:55Z

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

gsmolk · 2021-03-21T11:31:54Z

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

ykurenkov · 2021-03-21T17:38:39Z

А можете показать метаданные этого бэкапа и содержимое его директории 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 · 2021-03-21T18:03:17Z

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

gsmolk · 2021-03-21T21:57:34Z

pg_wal пустой.

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

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

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

gsmolk · 2021-03-21T21:58:29Z

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

gsmolk · 2021-03-21T22:03:03Z

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

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

ykurenkov · 2021-03-22T05:55:44Z

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

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

ykurenkov · 2021-03-22T06:14:45Z

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

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

gsmolk · 2021-03-22T11:01:26Z

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

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 · 2021-03-22T14:58:26Z

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

ykurenkov · 2021-03-22T15:16:44Z

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

gsmolk · 2021-03-22T17:11:13Z

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

…gment

gsmolk · 2021-03-22T18:39:33Z

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

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 · 2021-03-26T11:44:56Z

Даа, а если бы логирование в файл работало, то сколько бы времени сэкономили.
Будем пилить новый стриминг.
Закрываем?

ykurenkov · 2021-03-26T12:29:05Z

Не, это я об ошибке, когда бэкап завершился через 3-4 секунды после старта, о конкретном бэкапе.

gsmolk · 2021-03-26T12:34:21Z

А сейчас какие-то проблемы еще остались?

ykurenkov · 2021-03-26T12:57:24Z

Оставлю на выходные бэкапы в распоряжении crond, а на следующей неделе посмотрим статистику. В случае удачи стои таймауты стриминга уменьшать или на 240 пусть живет?

gsmolk · 2021-03-26T13:19:19Z

240 - норм

ykurenkov · 2021-03-31T05:26:33Z

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

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

240 - норм

Может это как-то связано с этим значением?

archive_timeout = 150

И параметры выше должны быть больше значения archive_timeout?

ykurenkov · 2021-04-06T05:26:33Z

Пока работает. Был только один странный сбой:

2021-04-03 03:06:53 +05 [11210]: ERROR: WAL segment 000000010000039F00000092 could not be streamed in 600 seconds
2021-04-03 03:06:53 +05 [11210]: WARNING: Backup QQY7C2 is running, setting its status to ERROR

У постгреса на это событие вот такие строчки в логе:

2021-04-03 03:06:54 +05 [unknown] postgres@[local] PID:11213 LOG:  08006: could not receive data from client: Connection reset by peer
2021-04-03 03:06:54 +05 [unknown] postgres@[local] PID:11213 LOCATION:  pq_getbyte_if_available, pqcomm.c:1074
2021-04-03 03:06:54 +05 [unknown] postgres@[local] PID:11213 LOG:  08P01: unexpected EOF on standby connection
2021-04-03 03:06:54 +05 [unknown] postgres@[local] PID:11213 LOCATION:  ProcessRepliesIfAny, walsender.c:1620

gsmolk · 2021-04-07T07:12:30Z

Выглядит как закрытие коннекта со стороны клиента.
Похоже, что probackup честно не дождался сегмента 000000010000039F00000092 за 600 секунд и завершился.

gsmolk · 2021-04-07T07:17:59Z

Может это как-то связано с этим значением?

archive_timeout = 150
И параметры выше должны быть больше значения archive_timeout?

Почти не связано, wal_sender_timeout - это таймаут при общении с клиентом по реппротоколу (как долго клиент может не отвечать на keep-alive).

ykurenkov · 2021-04-07T08:30:52Z

Выглядит как закрытие коннекта со стороны клиента.
Похоже, что probackup честно не дождался сегмента 000000010000039F00000092 за 600 секунд и завершился.

Тогда что ему помешало?

archive_timeout = 150

WALы ротейтятся каждые 150 секунд. И то не удалённый бэкап, а локальный. Что могло помешать в пределах одного хоста?

gsmolk · 2021-04-07T09:52:29Z

Что могло помешать в пределах одного хоста?

Нехватка ресурсов, например, медленное I/O.
verbose лог от этого кейса есть?

ykurenkov · 2021-04-07T12:10:20Z

Что могло помешать в пределах одного хоста?

Нехватка ресурсов, например, медленное I/O.

4 ядра и 32ГБ памяти для standby и pg_probackup - должно хватить.

verbose лог от этого кейса есть?

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

ccppprogrammer · 2021-04-19T04:57:16Z

I have the same problem. Only happens from time to time with a full backup.

OS

# cat /etc/redhat-release 
Red Hat Enterprise Linux Server release 7.5 (Maipo)
# uname -a
Linux xxx 3.10.0-693.2.2.el7.x86_64 #1 SMP Tue Sep 12 10:49:01 PDT 2017 x86_64 x86_64 x86_64 GNU/Linux

pg_probackup version

# rpm -q pg_probackup-9.6
pg_probackup-9.6-2.4.8-1.d9f95db7261c25c9.x86_64

PostgreSQL version

postgres=# select version();
                                                 version                                                  
----------------------------------------------------------------------------------------------------------
 PostgreSQL 9.6.5 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-11), 64-bit
(1 row)

wal_sender_timeout

postgres=# show wal_sender_timeout;
 wal_sender_timeout 
--------------------
 1min
(1 row)

wal_receiver_timeout

postgres=# show wal_receiver_timeout;
 wal_receiver_timeout 
----------------------
 1min
(1 row)

pg_probackup logs

2021-04-17 01:00:01 MSK [2091]: INFO: command: /usr/bin/pg_probackup-9.6 backup -B /var/lib/pg_probackup/ -b FULL --instance=xxx --threads=6 --stream --temp-slot 
2021-04-17 01:00:01 MSK [2091]: INFO: Backup start, pg_probackup version: 2.4.8, instance: xxx, backup ID: QROFS1, backup mode: FULL, wal mode: STREAM, remote: true, compress-algorithm: none, compress-level: 0
2021-04-17 01:00:01 MSK [2091]: LOG: Backup destination is initialized
2021-04-17 01:00:01 MSK [2091]: WARNING: This PostgreSQL instance was initialized without data block checksums. pg_probackup have no way to detect data block corruption without them. Reinitialize PGDATA with option '--data-checksums'.
2021-04-17 01:00:01 MSK [2091]: LOG: Start SSH client process, pid 2113
2021-04-17 01:00:02 MSK [2091]: LOG: Database backup start
2021-04-17 01:00:02 MSK [2091]: LOG: started streaming WAL at 2BDA/DD000000 (timeline 1)
2021-04-17 01:00:02 MSK [2091]: LOG: SSH process 2113 is terminated with status 0
2021-04-17 01:00:02 MSK [2091]: INFO: PGDATA size: 5806GB
2021-04-17 01:00:02 MSK [2091]: LOG: Current Start LSN: 2BDA/DD000028, TLI: 1
2021-04-17 01:00:03 MSK [2091]: INFO: Start transferring data files
2021-04-17 01:00:03 MSK [2091]: LOG: Start SSH client process, pid 2124
2021-04-17 01:00:03 MSK [2091]: LOG: Start SSH client process, pid 2125
2021-04-17 01:00:03 MSK [2091]: LOG: Start SSH client process, pid 2126
2021-04-17 01:00:03 MSK [2091]: LOG: Start SSH client process, pid 2128
2021-04-17 01:00:03 MSK [2091]: LOG: Start SSH client process, pid 2127
2021-04-17 01:00:03 MSK [2091]: LOG: Start SSH client process, pid 2129
2021-04-17 01:00:03 MSK [2091]: LOG: Creating page header map "/var/lib/pg_probackup/backups/xxx/QROFS1/page_header_map"
2021-04-17 01:13:16 MSK [2091]: ERROR: Problem in receivexlog
2021-04-17 01:13:17 MSK [2091]: ERROR: interrupted during backup
2021-04-17 01:13:20 MSK [2091]: ERROR: interrupted during backup
2021-04-17 01:13:20 MSK [2091]: ERROR: interrupted during backup
2021-04-17 01:13:22 MSK [2091]: ERROR: interrupted during backup
2021-04-17 01:13:23 MSK [2091]: ERROR: interrupted during backup
2021-04-17 01:13:23 MSK [2091]: ERROR: interrupted during backup
2021-04-17 01:13:23 MSK [2091]: ERROR: Data files transferring failed, time elapsed: 13m:20s
2021-04-17 01:13:23 MSK [2091]: WARNING: backup in progress, stop backup
2021-04-17 01:13:23 MSK [2091]: WARNING: Backup QROFS1 is running, setting its status to ERROR

pg_probackup logs from cron

INFO: Backup start, pg_probackup version: 2.4.8, instance: xxx, backup ID: QROFS1, backup mode: FULL, wal mode: STREAM, remote: true, compress-algorithm: none, compress-level: 0
WARNING: This PostgreSQL instance was initialized without data block checksums. pg_probackup have no way to detect data block corruption without them. Reinitialize PGDATA with option '--data-checksums'.
INFO: PGDATA size: 5806GB
INFO: Start transferring data files
(null): could not receive data from WAL stream: server closed the connection unexpectedly
        This probably means the server terminated abnormally
        before or while processing the request.
ERROR: Problem in receivexlog
ERROR: interrupted during backup
ERROR: interrupted during backup
ERROR: interrupted during backup
ERROR: interrupted during backup
ERROR: interrupted during backup
ERROR: interrupted during backup
ERROR: Data files transferring failed, time elapsed: 13m:20s
WARNING: backup in progress, stop backup
WARNING: Backup QROFS1 is running, setting its status to ERROR

gsmolk · 2021-04-23T11:26:36Z

Hello, @ccppprogrammer !
I think you have the case of postgres killing replication connect due to timeout.
To prove that we should check the postgresql log.
As a rule of thumb you should set the wal_sender_timeout parameter to a higher value.

ccppprogrammer · 2021-04-23T11:54:08Z

@gsmol you're right. In the PostgreSQL log I have:

#2021-04-17 01:00:02.373 MSK [7212]: [2-1] { user=pgprobackup,db=[unknown],c=607a08e2.1c2c,e=00000,x=0,a=[unknown],r=x.x.x.x(47420),i=authentication,v=59/38775517 } LOG:  replication connection authorized: user=pgprobackup
#2021-04-17 01:12:47.507 MSK [7212]: [3-1] { user=pgprobackup,db=[unknown],c=607a08e2.1c2c,e=00000,x=0,a=pg_probackup-9.6,r=x.x.x.x(47420),i=streaming 2BDA/DE9BE640,v=59/0 } LOG:  terminating walsender process due to replication timeout

gsmolk · 2021-04-23T12:19:54Z

Great!
New streaming engine #350 should resolve such issues once and for all

ykurenkov · 2021-09-28T06:34:55Z

2.4.10 работал с этими настройками без проблем. Обновил до 2.4.15, поскольку наткнулся на проблему с пустым backup.control. 2.4.15 во время трех дней активных попыток так и не смог завершить ни одного бэкапа. Сваливался с этой же ошибкой:

2021-09-23 17:55:36 +05 [31463]: INFO: Progress: (1761/16497). Process file "base/18983/30298"
2021-09-23 17:55:36 +05 [31463]: INFO: Progress: (1762/16497). Process file "base/18983/30294"
2021-09-23 17:55:36 +05 [31463]: ERROR: interrupted during backup
2021-09-23 17:55:36 +05 [31463]: ERROR: Problem in receivexlog
2021-09-23 17:55:36 +05 [31463]: ERROR: Data files transferring failed, time elapsed: 2h:9m
2021-09-23 17:55:36 +05 [31463]: WARNING: backup in progress, stop backup
2021-09-23 17:55:36 +05 [31463]: WARNING: Backup QZVUWO is running, setting its status to ERROR

В postgres.log в это время

2021-09-23 17:55:36.763 +05 [31770] LOG:  could not send data to client: Broken pipe
2021-09-23 17:55:36.763 +05 [31770] FATAL:  connection to client lost

Откатил до 2.4.10

gsmolk · 2021-10-30T13:17:24Z

Сейчас выпустим виндовые инсталлеры для 2.5.2 и можно будет попробовать его.

ykurenkov · 2021-12-24T14:05:55Z

Под Windows новее 2.4.15 так и нет инсталлеров?

kulaginm · 2021-12-24T14:08:29Z

@ykurenkov, к сожалению, пока не делаю их. но в планах.

gsmolk added the bug label Mar 22, 2021

gsmolk added this to the 2.4.12 milestone Mar 22, 2021

gsmolk added a commit that referenced this issue Mar 22, 2021

[Issue #346] set "interrupted" in elog, wait for streamed segments

0876dd6

gsmolk added a commit that referenced this issue Mar 22, 2021

[Issue #346] tests: added tests.backup.BackupTest.test_missing_wal_se…

c36ba06

…gment

gsmolk added a commit that referenced this issue Apr 23, 2021

[Issue #346] detect failure of streaming thread

82af8f3

kulaginm modified the milestones: 2.4.18, 2.5.3 Oct 15, 2021

kulaginm modified the milestones: 2.5.4, 2.5.5 Dec 22, 2021

kulaginm modified the milestones: 2.5.5, 2.5.6 Feb 16, 2022

kulaginm modified the milestones: 2.5.6, 2.5.7 May 26, 2022

Burus removed this from the 2.5.7 milestone Sep 14, 2022

pg_probackup 2.4.10: Problem in receivexlog #346

pg_probackup 2.4.10: Problem in receivexlog #346

Comments

ykurenkov commented Mar 15, 2021

gsmolk commented Mar 15, 2021

ykurenkov commented Mar 15, 2021

gsmolk commented Mar 15, 2021

ykurenkov commented Mar 15, 2021

gsmolk commented Mar 15, 2021

ykurenkov commented Mar 20, 2021 • edited

gsmolk commented Mar 20, 2021

ykurenkov commented Mar 20, 2021

gsmolk commented Mar 20, 2021

gsmolk commented Mar 20, 2021

ykurenkov commented Mar 20, 2021

ykurenkov commented Mar 21, 2021

gsmolk commented Mar 21, 2021 • edited

gsmolk commented Mar 21, 2021

ykurenkov commented Mar 21, 2021

ykurenkov commented Mar 21, 2021

gsmolk commented Mar 21, 2021

gsmolk commented Mar 21, 2021

gsmolk commented Mar 21, 2021 • edited

ykurenkov commented Mar 22, 2021

ykurenkov commented Mar 22, 2021

gsmolk commented Mar 22, 2021 • edited

gsmolk commented Mar 22, 2021

ykurenkov commented Mar 22, 2021 via email • edited

gsmolk commented Mar 22, 2021

gsmolk commented Mar 22, 2021

gsmolk commented Mar 26, 2021

ykurenkov commented Mar 26, 2021

gsmolk commented Mar 26, 2021

ykurenkov commented Mar 26, 2021

gsmolk commented Mar 26, 2021

ykurenkov commented Mar 31, 2021 • edited

ykurenkov commented Apr 6, 2021

gsmolk commented Apr 7, 2021

gsmolk commented Apr 7, 2021

ykurenkov commented Apr 7, 2021 • edited

gsmolk commented Apr 7, 2021

ykurenkov commented Apr 7, 2021 • edited

ccppprogrammer commented Apr 19, 2021

gsmolk commented Apr 23, 2021 • edited

ccppprogrammer commented Apr 23, 2021

gsmolk commented Apr 23, 2021 • edited

ykurenkov commented Sep 28, 2021 • edited

gsmolk commented Oct 30, 2021

ykurenkov commented Dec 24, 2021

kulaginm commented Dec 24, 2021

ykurenkov commented Mar 20, 2021 •

edited

gsmolk commented Mar 21, 2021 •

edited

gsmolk commented Mar 21, 2021 •

edited

gsmolk commented Mar 22, 2021 •

edited

ykurenkov commented Mar 22, 2021 via email •

edited

ykurenkov commented Mar 31, 2021 •

edited

ykurenkov commented Apr 7, 2021 •

edited

ykurenkov commented Apr 7, 2021 •

edited

gsmolk commented Apr 23, 2021 •

edited

gsmolk commented Apr 23, 2021 •

edited

ykurenkov commented Sep 28, 2021 •

edited