Re: BUG #15638: pg_basebackup with --wal-method=stream incorrectlygenerates WAL segment created during backup - Mailing list pgsql-bugs

I call pg_ctl -D /var/lib/pgsql/10/data promote to upgrade slave to master when failover happens. archive_mode is set to "on" and not "always".

I repoint slave to the master by stopping it, updating recovery.conf and restarting it. Let me know if I'm doing it wrong.

I think this problem is created before promotion when new slave is created using pg_basebackup with --wal-method=stream and manifests when actual promotion happens.

What I'm trying to say it does not seem that .partial extension is the issue here but lack of .done extension.

Wouldn't you agree that given directory contents below, when failover happens and new slave is promoted to the primary then with fetch mode master would should not archive 000000010000000000000002 segment because it is marked as .done but in stream method segment is not marked as .done so it would be attempted to be archived again? This obviously fails because segment has been archived by initial master. If you disagree, can you explain the purpose behind .done extension in pg_wal/archive_status directory?

Below are contents of directories after base backup but before promoting new slave to master status..

PRIMARY

/var/lib/pgsql/10/data/pg_wal/:

total 49156

-rw-------. 1 postgres postgres 16777216 Feb 15 13:39 000000010000000000000001

-rw-------. 1 postgres postgres 16777216 Feb 15 13:40 000000010000000000000002

-rw-------. 1 postgres postgres      302 Feb 15 13:40 000000010000000000000002.00000028.backup

-rw-------. 1 postgres postgres 16777216 Feb 15 13:40 000000010000000000000003

drwx------. 2 postgres postgres      133 Feb 15 13:40 archive_status

/var/lib/pgsql/10/data/pg_wal/archive_status:

total 0

-rw-------. 1 postgres postgres 0 Feb 15 13:39 000000010000000000000001.done

-rw-------. 1 postgres postgres 0 Feb 15 13:40 000000010000000000000002.00000028.backup.done

-rw-------. 1 postgres postgres 0 Feb 15 13:40 000000010000000000000002.done

WAL ARCHIVE

-rw-rw-rw-. 1 root root 16777216 Feb 15 13:39 000000010000000000000001

-rw-rw-rw-. 1 root root 16777216 Feb 15 13:40 000000010000000000000002

-rw-rw-rw-. 1 root root      302 Feb 15 13:40 000000010000000000000002.00000028.backup

NEW SLAVE (stream method)

-rw-------. 1 postgres root     16777216 Feb 15 13:40 000000010000000000000002

-rw-------. 1 postgres postgres 16777216 Feb 15 13:40 000000010000000000000003

drwx------. 2 postgres root            6 Feb 15 13:40 archive_status

/var/lib/pgsql/10/data/pg_wal/archive_status:

total 0

NEW SLAVE (stream method)

-rw-------. 1 postgres root     16777216 Feb 15 13:40 000000010000000000000002

-rw-------. 1 postgres postgres 16777216 Feb 15 13:40 000000010000000000000003

drwx------. 2 postgres root            6 Feb 15 13:40 archive_status

/var/lib/pgsql/10/data/pg_wal/archive_status:

total 0

NEW SLAVE (fetch method)

-rw-------. 1 postgres root     16777216 Feb 15 13:24 000000010000000000000002

-rw-------. 1 postgres postgres 16777216 Feb 15 13:24 000000010000000000000003

drwx------. 2 postgres root           43 Feb 15 13:24 archive_status

/var/lib/pgsql/10/data/pg_wal/archive_status:

total 0

-rw-------. 1 postgres root 0 Feb 15 13:24 000000010000000000000002.done

Eventual failover(s) produced this structure on master:

/var/lib/pgsql/10/data/pg_wal/archive_status:

total 0

-rw-------. 1 postgres postgres 0 Feb 15 14:15 000000010000000000000002.ready

Hence attempt to archive again:

2019-02-15 14:15:58.872 PST [5369] DETAIL:  The failed archive command was: test ! -f /mnt/pgsql/archive/000000010000000000000002 && cp pg_wal/000000010000000000000002 /mnt/pgsql/archive/000000010000000000000002

On Mon, Feb 18, 2019 at 9:03 AM Maksim Milyutin <milyutinma@gmail.com> wrote:

On 2/16/19 6:25 PM, Michael Paquier wrote:

On Sat, Feb 16, 2019 at 12:26:13AM +0000, PG Bug reporting form wrote:

When new slave is created by taking base backup from the primary using
pg_basebackup with --wal-method=stream option the WAL file generated during
the backup is different (as compared with diff or cmp command) than that on
the master and in WAL archive directory. Furthermore, this file does not
exist in pg_wal/archive_status with .done extension on new slave, though it
exists in pg_wal directory, resulting in failed attempt to archive this file
when slave node is promoted as master node.
2019-02-15 14:15:58.872 PST [5369] DETAIL:  The failed archive command was:
test ! -f /mnt/pgsql/archive/000000010000000000000002 && cp
pg_wal/000000010000000000000002
/mnt/pgsql/archive/000000010000000000000002

How do you promote your standby?  In Postgres 10, the last, partial
WAL segment of a past timeline generated at promotion is renamed
.partial to avoid any conflicts, so as this should normally not
happen if you do not use archive_mode = always.

This issue concerns only segment that contains wal records from pg_basebackup. For example, I have reproduced this issue on master branch getting the following content of archive directory after standby promoting:

000000010000000000000001.node1
000000010000000000000002.00000028.backup.node1
000000010000000000000002.node1
000000010000000000000002.node2
000000010000000000000003.node1
000000010000000000000004.node1
000000010000000000000005.partial.node2
000000020000000000000005.node2
00000002.history.node2

Each wal segment specifically was appended with .<node> suffix to distinguish its source. Initially the node1 was master, node2 - standby. The segment 000000010000000000000002 has the following content:

rmgr: Standby     len (rec/tot):     50/    50, tx:          0, lsn: 0/02000028, prev 0/015DB060, desc: RUNNING_XACTS nextXid 474 latestCompletedXid 473 oldestRunningXid 474
rmgr: XLOG        len (rec/tot):    106/   106, tx:          0, lsn: 0/02000060, prev 0/02000028, desc: CHECKPOINT_ONLINE redo 0/2000028; tli 1; prev tli 1; fpw true; xid 0:474; oid 12690; multi 1; offset 0; oldest xid 467 in DB 1; oldest multi 1 in DB 1; oldest/newest commit timestamp xid: 0/0; oldest running xid 474; online
rmgr: XLOG        len (rec/tot):     34/    34, tx:          0, lsn: 0/020000D0, prev 0/02000060, desc: BACKUP_END 0/2000028
rmgr: XLOG        len (rec/tot):     24/    24, tx:          0, lsn: 0/020000F8, prev 0/020000D0, desc: SWITCH

On the current state of master branch the content of two segments are the same:

$ md5sum 000000010000000000000002.node1 000000010000000000000002.node2

252e3e8cf3a85f218bb467005c565e3c  000000010000000000000002.node1
252e3e8cf3a85f218bb467005c565e3c  000000010000000000000002.node2

But on PG 10.6 the contents are differentiated on the tails:

$ cmp 000000010000000000000002.node1 000000010000000000000002.node2

000000010000000000000002.node1 000000010000000000000002.node2 differ: byte 131073, line 1

while logical part (prefix) are the same - the lsn of last record (SWITCH) in this segment is 0/02000130 and have length 24 bytes.

Is it correct behavior? What would be the correct canonical representation of archive command taking into account this issue?

-- 
Regards,
Maksim Milyutin

--

Andre Piwoni

Sr. Software Developer, BI/Database

WebMD Health Services

Mobile: 801.541.4722

www.webmdhealthservices.com