0

I'm running two postgresql servers and I'm trying to setup logical replication.

These are extra bits of configuration I added on master in order to make replication work:

wal_level=logical

max_replication_slots=10
max_wal_senders=10

# maximum wait time in milliseconds that the walsender process on the active master
# waits for a status message from the walreceiver process on the standby master.
wal_sender_timeout=600000
#wal_receiver_timeout=180000

These are extra bits of configuration on slave:

wal_level=logical
max_replication_slots=2
max_logical_replication_workers=4

wal_receiver_timeout=1200000

I have appropriate entries in pg_hba to provision access for replication user.

I followed postgresql guide and everything seems to work fine - that is I can see in log tables are replicated one by one. As soon as initial replication is completed I can see changes from master are applied on slave.

However at some random point I see this log on master:

2019-08-21 11:52:37.183,(...),"starting logical decoding for slot "my_slot_name","Streaming transactions committing after D35/AD4F438, reading WAL from D35/A1D85C0.",,,,,,,,"my_slot_name"
2019-08-21 11:52:37.184,(...),"logical decoding found consistent point at D35/A1D85C0","Logical decoding will begin using saved snapshot.",,,,,,,,"my_slot_name"

This is then immediately followed with this log on slave:

2019-08-21 11:52:36.932 [4411] ERROR:  could not send data to WAL stream: server closed the connection unexpectedly
                This probably means the server terminated abnormally
                before or while processing the request.
2019-08-21 11:52:36.977 [14438] LOG:  logical replication apply worker for subscription "my_subscription_name" has started
2019-08-21 11:52:36.987 [27972] LOG:  background worker "logical replication worker" (PID 4411) exited with exit code 1

I have done some reading and found this mailing list thread and based on advice I increased value of wal_sender_timeout on master from 60 seconds to 300 seconds initially. However the problem still seems to persist...

Also each time I try something new I have to reinitialize replication from scratch which takes lots of time, I was wondering if I can point slave on WAL archives from master so it would replay missing WALs..?

I would appreciate any advice for directions how to approach debugging this problem...


Edit: I think I found the way to reinitialize replication:

ALTER SUBSCRIPTION my_subscription_name DISABLE;
ALTER SUBSCRIPTION my_subscription_name ENABLE;
ALTER SUBSCRIPTION my_subscription_name REFRESH PUBLICATION;

The original problem still persists though..


I ended up setting wal_sender_timeout to 20 minutes and this cleared errors away for me. I still need to get to the bottom of this to understand what was causing this behavior.


Edit (month later)

I came across this great presentation, it is pointing at documentation saying:

a block containing an EXCEPTION clause effectively
forms a subtransaction that can be rolled back without
affecting the outer transaction.

They had BEGIN (...) EXCEPTION WHEN (...) TEN (...) END clause used in archiving trigger. There we go, this is what I see in my schema! That means some refactoring in front of me.

And also wonderful reading mentioned in that PDF worth to look at: https://blog.anayrat.info/en/2018/03/10/logical-replication-internals/ and https://www.postgresql.org/message-id/688b0b7f-2f6c-d827-c27b-216a8e3ea700@2ndquadrant.com

So that's what I'm going to explore now and hopefully report back with final answer.

  • What versions of postgresql are you using? Is there an actual problem here? That is, doesn't it just reconnect and continue on its way? – jjanes Aug 21 at 14:17
  • Both master and slave are on version 11.3 It does (seem to) reconnect however if afterwards I insert to table on master I can't see the change being propagated to slave. – Greg0ry Aug 22 at 5:59
  • There should be an error message on the master's log file corresponding to the replica's message at 2019-08-21 11:52:36.932. Can you find one? If it reconnects but doesn't make any progress, there should also be more messages on the replica's log file about that. Also, it wouldn't hurt to upgrade to 11.5, though I have no specific reason to think it will solve the problem. I can't reproduce the problem myself to study it further. – jjanes Aug 22 at 20:32
  • Hi @jjanes - there are no corresponding errors on master (last occurrence of slave failing was at 8:30:30am and the only corresponding log on master was the same log I already mentioned in the question - starting logical decoding for slot); I have been increasing wal_sender_timeout after each occurrence of the issue and I can see the frequency is getting lower (I did not see this error since I last time increased wal_sender_timeout yesterday at 8:30:30am); I need to read postgres docs on possible side effects of having large wal_sender_timeout... – Greg0ry Aug 23 at 5:43
  • I think for now I'll settle with wal_sender_timeout solution though it does not feel viable. I'd like to understand why this timeout is hit, can this be caused by long transaction on master resulting in lots of data committed in one go? – Greg0ry Aug 23 at 7:27

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.