scenario.md

application/octet-stream

Download

0. Apply patch

I've tested this scenario on HEAD (009f8d17146da72478fcb8f544b793c443fa254c).

Apply the test.patch and build with "--enable-cassert --enable-debug --enable-tap-tests CFLAGS=-O0"

1. Setup publisher.

Create the database cluster with checksum and append the following settings:

wal_level = logical
autovacuum = off
max_wal_size = 512MB
min_wal_size = 80MB
wal_sender_timeout = 1min
log_min_messages = debug2

2. Setup subscriber.

Create the database cluster with checksum and append the following settings:

wal_level = logical
wal_receiver_status_interval = 10s

3. Create a table on both nodes.

create table test (c int);

4. Create a publication.

create publication test_pub for table test;

5. Create a subscription.

create subscription test_sub connection 'dbname=postgres port=5551' publication test_pub with (copy_data = 'false');

6. Insert a row and create a checkpoint.

insert into test values(1);
checkpoint; -- CHECKPOINT-1 (at around 0/1734F18)

7. Run four concurrent transactions.

client-1:
begin; -- XID=732
insert into test values(1);

    client-2:
    checkpoint; -- CHECKPOINT-2 (at around 0/1735068)

        client-3:
        begin; -- XID=733
        create table test2 (c int);
        insert into test2 values(2);
        insert into test values(1);

commit;

            client-4:
            begin;
            insert into test values(1);
            commit;
            select pg_switch_wal();
            (repeat above queries 6 times)

    checkpoint; -- CHECKPOINT-3 (at around 0/7000108)

        commit;

8. Run four concurrent transactions.

client-1:
begin; -- XID=740
create table test3 (c int);
insert into test3 values (3);
insert into test values (1);

    client-2:
    begin;
    insert into test values(1);
    select pg_switch_wal();
    commit;
    (repeat above queries 6 times)

        client-3:
        checkpoint; -- CHECKPOINT-4 (at around 0/D000108)

            client-4:
            begin; -- XID=747
            insert into test values(1);
            commit;
            select pg_switch_wal();

commit;

9. The apply worker starts waiting for 1min.

Because of the change for apply_handle_commit() made by the test.patch, the apply worker will stop *after* committing the transaction with xid=744 and *before* sending an ack with flush > 0/D000108. So you will see the log on the subscriber:

LOG:  XXX committed xid 744 origin lsn 0/A000098, sleep 60s

10. Wait for the apply worker to exit due to the wal_sender_timeout.

Since the apply worker sleeps for 1min and wal_sender_timeout is 1min, the walsender exits. After the walsender restarts, it acquires the slot whose candidate_restart_lsn/valid are not reset. You will see the following log on the publisher after the walsender restarts:

LOG:  XXX acquired slot restart_lsn 0/1734FB8 candidate_restart_lsn 0/7000058 candidate_restart_valid 0/D000058

On subscriber, the origin lsn is already greater than 0/D000058. Therefore, it sends an ack so that the walsender accepts the (unreset) candidate_restart_lsn[1]. In my environment, the first ack after restart from the apply worker is:

DEBUG:  write 0/E0001C0 flush 0/E0001C0 apply 0/E0001C0 reply_time 2023-02-06 16:27:53.094892+09

11. Run CHECKPOITN after temporarily updating candidate_restart_lsn.

See the publisher log carefully and execute "CHECKPOINT" on the publisher as soon as you see the log like:

DEBUG:  got new restart lsn 0/1734FB8 at 0/7000058

This means that slot's candidate_restart_lsn is 0/173AA90 although the current slot's restart_lsn is 0/7000058.

The checkpoint removes WAL files older than 000000010000000000000006.

12. The walsender errors out and restarts.

Because of the change in LogicalConfirmReceivedLocation() made by the test.patch, the walsender exits after moving the slot's restart_lsn backward (i.e. 0/7000058 -> 0/1734FB8). This simulates the walsender exists due to another timeout after moving its restart_lsn backward.

13. WAL is already removed.

You will see the following logs:

ERROR:  requested WAL segment 000000010000000000000001 has already been removed

or the replication slot is already invalidated with the following logs:

ERROR:  cannot read from logical replication slot "test_sub"
DETAIL:  This slot has been invalidated because it exceeded the maximum reserved size.
STATEMENT:  START_REPLICATION SLOT "test_sub" LOGICAL 0/E0001C0 (proto_version '4', origin 'any', publication_names '"test_pub"')

[1] the apply worker calls "start_apply(origin_startpos)" and it sends this position as recvpos, writepos, and flushpos:

if (!have_pending_txes)
	flushpos = writepos = recvpos;