Thread: WAL recycled despite logical replication slot
While testing something else (whether "terminating walsender process due to replication timeout" was happening spuriously), I had logical replication set up streaming a default pgbench transaction load, with the publisher being 13devel-e1c8743 and subscriber being 12BETA4. Eventually I started getting errors about requested wal segments being already removed:
10863 sub idle 00000 2019-09-19 17:14:58.140 EDT LOG: starting logical decoding for slot "sub"
10863 sub idle 00000 2019-09-19 17:14:58.140 EDT DETAIL: Streaming transactions committing after 79/EB0B17A0, reading WAL from 79/E70736A0.
10863 sub idle 58P01 2019-09-19 17:14:58.140 EDT ERROR: requested WAL segment 0000000100000079000000E7 has already been removed
10863 sub idle 00000 2019-09-19 17:14:58.144 EDT LOG: disconnection: session time: 0:00:00.030 user=jjanes database=jjanes host=10.0.2.2 port=40830
10863 sub idle 00000 2019-09-19 17:14:58.140 EDT DETAIL: Streaming transactions committing after 79/EB0B17A0, reading WAL from 79/E70736A0.
10863 sub idle 58P01 2019-09-19 17:14:58.140 EDT ERROR: requested WAL segment 0000000100000079000000E7 has already been removed
10863 sub idle 00000 2019-09-19 17:14:58.144 EDT LOG: disconnection: session time: 0:00:00.030 user=jjanes database=jjanes host=10.0.2.2 port=40830
It had been streaming for about 50 minutes before the error showed up, and it showed right when streaming was restarting after one of the replication timeouts.
Is there an innocent explanation for this? I thought logical replication slots provided an iron-clad guarantee that WAL would be retained until it was no longer needed. I am just using pub/sub, none of the lower level stuff.
Cheers,
Jeff
On Fri, Sep 20, 2019 at 08:45:34AM -0400, Jeff Janes wrote: >While testing something else (whether "terminating walsender process due to >replication timeout" was happening spuriously), I had logical replication >set up streaming a default pgbench transaction load, with the publisher >being 13devel-e1c8743 and subscriber being 12BETA4. Eventually I started >getting errors about requested wal segments being already removed: > >10863 sub idle 00000 2019-09-19 17:14:58.140 EDT LOG: starting logical >decoding for slot "sub" >10863 sub idle 00000 2019-09-19 17:14:58.140 EDT DETAIL: Streaming >transactions committing after 79/EB0B17A0, reading WAL from 79/E70736A0. >10863 sub idle 58P01 2019-09-19 17:14:58.140 EDT ERROR: requested WAL >segment 0000000100000079000000E7 has already been removed >10863 sub idle 00000 2019-09-19 17:14:58.144 EDT LOG: disconnection: >session time: 0:00:00.030 user=jjanes database=jjanes host=10.0.2.2 >port=40830 > >It had been streaming for about 50 minutes before the error showed up, and >it showed right when streaming was restarting after one of the replication >timeouts. > >Is there an innocent explanation for this? I thought logical replication >slots provided an iron-clad guarantee that WAL would be retained until it >was no longer needed. I am just using pub/sub, none of the lower level >stuff. > I think you're right - this should not happen with replication slots. Can you provide more detailed setup instructions, so that I can try to reproduce and investigate the isssue? regards -- Tomas Vondra http://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Hi, On September 20, 2019 5:45:34 AM PDT, Jeff Janes <jeff.janes@gmail.com> wrote: >While testing something else (whether "terminating walsender process >due to >replication timeout" was happening spuriously), I had logical >replication >set up streaming a default pgbench transaction load, with the publisher >being 13devel-e1c8743 and subscriber being 12BETA4. Eventually I >started >getting errors about requested wal segments being already removed: > >10863 sub idle 00000 2019-09-19 17:14:58.140 EDT LOG: starting logical >decoding for slot "sub" >10863 sub idle 00000 2019-09-19 17:14:58.140 EDT DETAIL: Streaming >transactions committing after 79/EB0B17A0, reading WAL from >79/E70736A0. >10863 sub idle 58P01 2019-09-19 17:14:58.140 EDT ERROR: requested WAL >segment 0000000100000079000000E7 has already been removed >10863 sub idle 00000 2019-09-19 17:14:58.144 EDT LOG: disconnection: >session time: 0:00:00.030 user=jjanes database=jjanes host=10.0.2.2 >port=40830 > >It had been streaming for about 50 minutes before the error showed up, >and >it showed right when streaming was restarting after one of the >replication >timeouts. > >Is there an innocent explanation for this? I thought logical >replication >slots provided an iron-clad guarantee that WAL would be retained until >it >was no longer needed. I am just using pub/sub, none of the lower level >stuff. It indeed should. What's the content of pg_replication_slot for that slot? Andres -- Sent from my Android device with K-9 Mail. Please excuse my brevity.
On Fri, Sep 20, 2019 at 11:27 AM Tomas Vondra <tomas.vondra@2ndquadrant.com> wrote:
>
>Is there an innocent explanation for this? I thought logical replication
>slots provided an iron-clad guarantee that WAL would be retained until it
>was no longer needed. I am just using pub/sub, none of the lower level
>stuff.
>
I think you're right - this should not happen with replication slots.
Can you provide more detailed setup instructions, so that I can try to
reproduce and investigate the isssue?
It is a bit messy, because this isn't what I was trying to test.
The basic set up is pretty simple:
On master:
pgbench -i -s 100
create publication pgbench for table pgbench_accounts, pgbench_branches, pgbench_history , pgbench_tellers;
pgbench -R200 -c4 -j4 -P60 -T360000 -n
on replica:
pgbench -i -s 1
truncate pgbench_history , pgbench_accounts, pgbench_branches, pgbench_tellers;
create subscription sub CONNECTION 'host=192.168.0.15' publication pgbench;
create subscription sub CONNECTION 'host=192.168.0.15' publication pgbench;
The messy part: It looked like the synch was never going to finish, so first I cut the rate down to -R20. Then what I thought I did was drop the primary key on pgbench_accounts (manually doing a kill -15 on the synch worker to release the lock), wait for the copy to start again and then finish and then start getting "ERROR: logical replication target relation "public.pgbench_accounts" has neither REPLICA IDENTITY index nor PRIMARY KEY and published relation does not have REPLICA IDENTITY FULL" log messages, then I re-added the primary key. Then I increased the -R back to 200, and about 50 minutes later got the WAL already removed error.
But now I can't seem to reproduce this, as the next time I tried to do the synch with no primary key there doesn't seem to be a commit after the COPY finishes so once it tries to replay the first update, it hits the above "no primary key" error and then rolls back the **the entire COPY** as well as the single-row update, and starts the entire COPY over again before you have a chance to intervene and build the index. So I'm guessing now that either the lack of a commit (which itself seems like a spectacularly bad idea) is situation dependent, or the very slow COPY had finished between the time I had decided to drop the primary key, and time I actually implemented the drop.
Perhaps important here is that the replica is rather underpowered. Write IO and fsyncs periodically become painfully slow, which is probably why there are replication timeouts, and since the problem happened when trying to reestablish after a timeout I would guess that that is critical to the issue.
I was running the master with fsync=off, but since the OS never crashed that should not be the source of corruption.
I'll try some more to reproduce this, but I wanted to make sure there was actually something here to reproduce, and not just my misunderstanding of how things are supposed to work.
Cheers,
Jeff
On Fri, Sep 20, 2019 at 6:25 PM Andres Freund <andres@anarazel.de> wrote:
Hi,
On September 20, 2019 5:45:34 AM PDT, Jeff Janes <jeff.janes@gmail.com> wrote:
>While testing something else (whether "terminating walsender process
>due to
>replication timeout" was happening spuriously), I had logical
>replication
>set up streaming a default pgbench transaction load, with the publisher
>being 13devel-e1c8743 and subscriber being 12BETA4. Eventually I
>started
>getting errors about requested wal segments being already removed:
>
>10863 sub idle 00000 2019-09-19 17:14:58.140 EDT LOG: starting logical
>decoding for slot "sub"
>10863 sub idle 00000 2019-09-19 17:14:58.140 EDT DETAIL: Streaming
>transactions committing after 79/EB0B17A0, reading WAL from
>79/E70736A0.
>10863 sub idle 58P01 2019-09-19 17:14:58.140 EDT ERROR: requested WAL
>segment 0000000100000079000000E7 has already been removed
>10863 sub idle 00000 2019-09-19 17:14:58.144 EDT LOG: disconnection:
>session time: 0:00:00.030 user=jjanes database=jjanes host=10.0.2.2
>port=40830
>
>It had been streaming for about 50 minutes before the error showed up,
>and
>it showed right when streaming was restarting after one of the
>replication
>timeouts.
>
>Is there an innocent explanation for this? I thought logical
>replication
>slots provided an iron-clad guarantee that WAL would be retained until
>it
>was no longer needed. I am just using pub/sub, none of the lower level
>stuff.
It indeed should. What's the content of
pg_replication_slot for that slot?
Unfortunately I don't think I have that preserved. If I can reproduce the issue, would preserving data/pg_replslot/sub/state help as well?
Cheers,
Jeff
Hi, On 2019-09-22 11:45:05 -0400, Jeff Janes wrote: > On Fri, Sep 20, 2019 at 6:25 PM Andres Freund <andres@anarazel.de> wrote: > > Hi, > > >Is there an innocent explanation for this? I thought logical > > >replication > > >slots provided an iron-clad guarantee that WAL would be retained until > > >it > > >was no longer needed. I am just using pub/sub, none of the lower level > > >stuff. > > > > It indeed should. What's the content of > > pg_replication_slot for that slot? > > > > Unfortunately I don't think I have that preserved. If I can reproduce the > issue, would preserving data/pg_replslot/sub/state help as well? Can't hurt. Best together with other slots, if they exists. Could you describe the system a bit? Greetings, Andres Freund