Thread: Subscription stuck at initialize state

I have 2 sets of publication/subscription between my 2 DBs.

One of them is working fine and the other one is stuck at initializing state for all the tables.

sourcedb=# select * from pg_publication;
  oid  |        pubname         | pubowner | puballtables | pubinsert | pubupdate | pubdelete | pubtruncate | pubviaroot
-------+------------------------+----------+--------------+-----------+-----------+-----------+-------------+------------
 19585 | omx_archive_big_tables |    16420 | f            | t         | t         | t         | t           | f
 19584 | omx_archive                    |    16420 | f            | t         | t         | t         | t           | f

targetdb=# select * from pg_subscription_rel ;
  srsubid   |  srrelid   | srsubstate |   srsublsn
------------+------------+------------+---------------
 3615804367 | 3322052690 | i          |
 3615804367 | 3322052570 | i          |
 3615756798 | 3322051793 | r          | 9E7E/BF5F82D8
 3615804367 | 3322052133 | i          |
 3615804367 | 3322054214 | i          |
 3615756798 | 3322051802 | r          | 9E7E/C149BBD8
 3615804367 | 3322051757 | i          |

targetdb=# select * from pg_subscription;
-[ RECORD 1 ]---+----------------------------------------------------------------------------------------------------------
oid             | 3615756798
subdbid         | 16589
subname         | sub_omx_archive_big_tables_tci
subowner        | 16420
subenabled      | t
subconninfo     | xxx
subslotname     | sub_omx_archive_big_tables_tci
subsynccommit   | off
subpublications | {omx_archive_big_tables}
-[ RECORD 2 ]---+----------------------------------------------------------------------------------------------------------
oid             | 3615804367
subdbid         | 16589
subname         | sub_omx_archive_tci
subowner        | 16420
subenabled      | t
subconninfo     | xxxx
subslotname     | sub_omx_archive_tci
subsynccommit   | off
subpublications | {omx_archive}

I have dropped the subscription, recreated and refreshed it many times, but it won't move from the initializing phase.

Any suggestions on how to start copying the data again, other than dropping the publication and re-creating it?

This correspondence (including any attachments) is for the intended recipient(s) only. It may contain confidential or privileged information or both. No confidentiality or privilege is waived or lost by any mis-transmission. If you receive this correspondence by mistake, please contact the sender immediately, delete this correspondence (and all attachments) and destroy any hard copies. You must not use, disclose, copy, distribute or rely on any part of this correspondence (including any attachments) if you are not the intended recipient(s).本メッセージに記載および添付されている情報（以下、総称して「本情報」といいます。）は、本来の受信者による使用のみを意図しています。誤送信等により本情報を取得された場合でも、本情報に係る秘密、または法律上の秘匿特権が失われるものではありません。本電子メールを受取られた方が、本来の受信者ではない場合には、本情報及びそのコピーすべてを削除・破棄し、本電子メールが誤って届いた旨を発信者宛てにご通知下さいますようお願いします。本情報の閲覧、発信または本情報に基づくいかなる行為も明確に禁止されていることをご了承ください。

Hi Abishek,

Have you checked the subscriber and publisher database log files to see if there is a problem blocking the subscription? For example, a subscribed table missing a column that exists in the publisher.

Cheers,

Steve

On Wed, Feb 2, 2022 at 1:26 PM Abhishek Bhola <abhishek.bhola@japannext.co.jp> wrote:

I have 2 sets of publication/subscription between my 2 DBs.

One of them is working fine and the other one is stuck at initializing state for all the tables.

sourcedb=# select * from pg_publication;
  oid  |        pubname         | pubowner | puballtables | pubinsert | pubupdate | pubdelete | pubtruncate | pubviaroot
-------+------------------------+----------+--------------+-----------+-----------+-----------+-------------+------------
 19585 | omx_archive_big_tables |    16420 | f            | t         | t         | t         | t           | f
 19584 | omx_archive                    |    16420 | f            | t         | t         | t         | t           | f

targetdb=# select * from pg_subscription_rel ;
  srsubid   |  srrelid   | srsubstate |   srsublsn
------------+------------+------------+---------------
 3615804367 | 3322052690 | i          |
 3615804367 | 3322052570 | i          |
 3615756798 | 3322051793 | r          | 9E7E/BF5F82D8
 3615804367 | 3322052133 | i          |
 3615804367 | 3322054214 | i          |
 3615756798 | 3322051802 | r          | 9E7E/C149BBD8
 3615804367 | 3322051757 | i          |

targetdb=# select * from pg_subscription;
-[ RECORD 1 ]---+----------------------------------------------------------------------------------------------------------
oid             | 3615756798
subdbid         | 16589
subname         | sub_omx_archive_big_tables_tci
subowner        | 16420
subenabled      | t
subconninfo     | xxx
subslotname     | sub_omx_archive_big_tables_tci
subsynccommit   | off
subpublications | {omx_archive_big_tables}
-[ RECORD 2 ]---+----------------------------------------------------------------------------------------------------------
oid             | 3615804367
subdbid         | 16589
subname         | sub_omx_archive_tci
subowner        | 16420
subenabled      | t
subconninfo     | xxxx
subslotname     | sub_omx_archive_tci
subsynccommit   | off
subpublications | {omx_archive}

I have dropped the subscription, recreated and refreshed it many times, but it won't move from the initializing phase.

Any suggestions on how to start copying the data again, other than dropping the publication and re-creating it?

This correspondence (including any attachments) is for the intended recipient(s) only. It may contain confidential or privileged information or both. No confidentiality or privilege is waived or lost by any mis-transmission. If you receive this correspondence by mistake, please contact the sender immediately, delete this correspondence (and all attachments) and destroy any hard copies. You must not use, disclose, copy, distribute or rely on any part of this correspondence (including any attachments) if you are not the intended recipient(s).本メッセージに記載および添付されている情報（以下、総称して「本情報」といいます。）は、本来の受信者による使用のみを意図しています。誤送信等により本情報を取得された場合でも、本情報に係る秘密、または法律上の秘匿特権が失われるものではありません。本電子メールを受取られた方が、本来の受信者ではない場合には、本情報及びそのコピーすべてを削除・破棄し、本電子メールが誤って届いた旨を発信者宛てにご通知下さいますようお願いします。本情報の閲覧、発信または本情報に基づくいかなる行為も明確に禁止されていることをご了承ください。

The only statement I see on the target DB log is
"logical replication apply worker for subscription ""sub_omx_archive_tci"" has started",,,,,,,,,""

I don't see the logical replication table synchronization worker started for any of the tables in this subscription as I see in the other one.

Is there anything in particular that I should be looking for in the log files?

On Wed, Feb 2, 2022 at 11:31 AM Steve Baldwin <steve.baldwin@gmail.com> wrote:

Hi Abishek,

Have you checked the subscriber and publisher database log files to see if there is a problem blocking the subscription? For example, a subscribed table missing a column that exists in the publisher.

Cheers,

Steve

On Wed, Feb 2, 2022 at 1:26 PM Abhishek Bhola <abhishek.bhola@japannext.co.jp> wrote:

I have 2 sets of publication/subscription between my 2 DBs.

One of them is working fine and the other one is stuck at initializing state for all the tables.

sourcedb=# select * from pg_publication;
  oid  |        pubname         | pubowner | puballtables | pubinsert | pubupdate | pubdelete | pubtruncate | pubviaroot
-------+------------------------+----------+--------------+-----------+-----------+-----------+-------------+------------
 19585 | omx_archive_big_tables |    16420 | f            | t         | t         | t         | t           | f
 19584 | omx_archive                    |    16420 | f            | t         | t         | t         | t           | f

targetdb=# select * from pg_subscription_rel ;
  srsubid   |  srrelid   | srsubstate |   srsublsn
------------+------------+------------+---------------
 3615804367 | 3322052690 | i          |
 3615804367 | 3322052570 | i          |
 3615756798 | 3322051793 | r          | 9E7E/BF5F82D8
 3615804367 | 3322052133 | i          |
 3615804367 | 3322054214 | i          |
 3615756798 | 3322051802 | r          | 9E7E/C149BBD8
 3615804367 | 3322051757 | i          |

targetdb=# select * from pg_subscription;
-[ RECORD 1 ]---+----------------------------------------------------------------------------------------------------------
oid             | 3615756798
subdbid         | 16589
subname         | sub_omx_archive_big_tables_tci
subowner        | 16420
subenabled      | t
subconninfo     | xxx
subslotname     | sub_omx_archive_big_tables_tci
subsynccommit   | off
subpublications | {omx_archive_big_tables}
-[ RECORD 2 ]---+----------------------------------------------------------------------------------------------------------
oid             | 3615804367
subdbid         | 16589
subname         | sub_omx_archive_tci
subowner        | 16420
subenabled      | t
subconninfo     | xxxx
subslotname     | sub_omx_archive_tci
subsynccommit   | off
subpublications | {omx_archive}

I have dropped the subscription, recreated and refreshed it many times, but it won't move from the initializing phase.

Any suggestions on how to start copying the data again, other than dropping the publication and re-creating it?

This correspondence (including any attachments) is for the intended recipient(s) only. It may contain confidential or privileged information or both. No confidentiality or privilege is waived or lost by any mis-transmission. If you receive this correspondence by mistake, please contact the sender immediately, delete this correspondence (and all attachments) and destroy any hard copies. You must not use, disclose, copy, distribute or rely on any part of this correspondence (including any attachments) if you are not the intended recipient(s).本メッセージに記載および添付されている情報（以下、総称して「本情報」といいます。）は、本来の受信者による使用のみを意図しています。誤送信等により本情報を取得された場合でも、本情報に係る秘密、または法律上の秘匿特権が失われるものではありません。本電子メールを受取られた方が、本来の受信者ではない場合には、本情報及びそのコピーすべてを削除・破棄し、本電子メールが誤って届いた旨を発信者宛てにご通知下さいますようお願いします。本情報の閲覧、発信または本情報に基づくいかなる行為も明確に禁止されていることをご了承ください。

Update: Tried dropping and recreating publication on the source DB and subscription still won't move ahead.

Not sure what I am missing.

On Wed, Feb 2, 2022 at 1:20 PM Abhishek Bhola <abhishek.bhola@japannext.co.jp> wrote:

The only statement I see on the target DB log is
"logical replication apply worker for subscription ""sub_omx_archive_tci"" has started",,,,,,,,,""

I don't see the logical replication table synchronization worker started for any of the tables in this subscription as I see in the other one.

Is there anything in particular that I should be looking for in the log files?

On Wed, Feb 2, 2022 at 11:31 AM Steve Baldwin <steve.baldwin@gmail.com> wrote:

Hi Abishek,

Have you checked the subscriber and publisher database log files to see if there is a problem blocking the subscription? For example, a subscribed table missing a column that exists in the publisher.

Cheers,

Steve

On Wed, Feb 2, 2022 at 1:26 PM Abhishek Bhola <abhishek.bhola@japannext.co.jp> wrote:

I have 2 sets of publication/subscription between my 2 DBs.

One of them is working fine and the other one is stuck at initializing state for all the tables.

sourcedb=# select * from pg_publication;
  oid  |        pubname         | pubowner | puballtables | pubinsert | pubupdate | pubdelete | pubtruncate | pubviaroot
-------+------------------------+----------+--------------+-----------+-----------+-----------+-------------+------------
 19585 | omx_archive_big_tables |    16420 | f            | t         | t         | t         | t           | f
 19584 | omx_archive                    |    16420 | f            | t         | t         | t         | t           | f

targetdb=# select * from pg_subscription_rel ;
  srsubid   |  srrelid   | srsubstate |   srsublsn
------------+------------+------------+---------------
 3615804367 | 3322052690 | i          |
 3615804367 | 3322052570 | i          |
 3615756798 | 3322051793 | r          | 9E7E/BF5F82D8
 3615804367 | 3322052133 | i          |
 3615804367 | 3322054214 | i          |
 3615756798 | 3322051802 | r          | 9E7E/C149BBD8
 3615804367 | 3322051757 | i          |

targetdb=# select * from pg_subscription;
-[ RECORD 1 ]---+----------------------------------------------------------------------------------------------------------
oid             | 3615756798
subdbid         | 16589
subname         | sub_omx_archive_big_tables_tci
subowner        | 16420
subenabled      | t
subconninfo     | xxx
subslotname     | sub_omx_archive_big_tables_tci
subsynccommit   | off
subpublications | {omx_archive_big_tables}
-[ RECORD 2 ]---+----------------------------------------------------------------------------------------------------------
oid             | 3615804367
subdbid         | 16589
subname         | sub_omx_archive_tci
subowner        | 16420
subenabled      | t
subconninfo     | xxxx
subslotname     | sub_omx_archive_tci
subsynccommit   | off
subpublications | {omx_archive}

I have dropped the subscription, recreated and refreshed it many times, but it won't move from the initializing phase.

Any suggestions on how to start copying the data again, other than dropping the publication and re-creating it?

This correspondence (including any attachments) is for the intended recipient(s) only. It may contain confidential or privileged information or both. No confidentiality or privilege is waived or lost by any mis-transmission. If you receive this correspondence by mistake, please contact the sender immediately, delete this correspondence (and all attachments) and destroy any hard copies. You must not use, disclose, copy, distribute or rely on any part of this correspondence (including any attachments) if you are not the intended recipient(s).本メッセージに記載および添付されている情報（以下、総称して「本情報」といいます。）は、本来の受信者による使用のみを意図しています。誤送信等により本情報を取得された場合でも、本情報に係る秘密、または法律上の秘匿特権が失われるものではありません。本電子メールを受取られた方が、本来の受信者ではない場合には、本情報及びそのコピーすべてを削除・破棄し、本電子メールが誤って届いた旨を発信者宛てにご通知下さいますようお願いします。本情報の閲覧、発信または本情報に基づくいかなる行為も明確に禁止されていることをご了承ください。

On Thu, Feb 3, 2022, 10:32 AM Abhishek Bhola <abhishek.bhola@japannext.co.jp> wrote:

So far I figured out that the problem is on the subscriber side.

The same publication, when subscribed to on another DB, works fine.

Also noticed that the remote_lsn value on the target DB is still 0/0.

targetdb=# select * from pg_replication_origin_status ;
 local_id |  external_id  |   remote_lsn   |   local_lsn
----------+---------------+----------------+----------------
        1 | pg_3615756798 | 9E96/37152C80  | 1518C/9014BD98
        2 | pg_3616584803 | 0/0                       | 0/0
(2 rows)

Would really appreciate it if someone could help me with this.

On Thu, Feb 3, 2022 at 9:53 AM Abhishek Bhola <abhishek.bhola@japannext.co.jp> wrote:

Update: Tried dropping and recreating publication on the source DB and subscription still won't move ahead.

Not sure what I am missing.

On Wed, Feb 2, 2022 at 1:20 PM Abhishek Bhola <abhishek.bhola@japannext.co.jp> wrote:

The only statement I see on the target DB log is
"logical replication apply worker for subscription ""sub_omx_archive_tci"" has started",,,,,,,,,""

I don't see the logical replication table synchronization worker started for any of the tables in this subscription as I see in the other one.

This might help you track subscription state along with pg_stat_subscription.

https://www.postgresql.org/docs/10/catalog-pg-subscription-rel.html

It might be a huge table being 'copy' ed and writes would be slow due to too many indexes etc.

https://postgresteam.slack.com/files/UQMFAU01W/F02V69YK59P/untitled.sql

also if you see nothing is moving, you may want to login to the server and strace the worker processes pid to see if you see any movement at all or it keeps looping on some errors.

On Thu, 3 Feb 2022 at 12:44, Abhishek Bhola <abhishek.bhola@japannext.co.jp> wrote:

Hi Vijaykumar,

I checked the pg_subscription_rel and all the tables in that subscription are in the state - i (initialize).

I also tried creating a new publication on the source DB with just one table and tried to subscribe it, it doesn't work either.

However, when I try to subscribe it on some other DB than the one mentioned above, it works. 

By which I am deducing that publication and the source DB are okay, the problem is on the target DB and it's subscription. 

Maybe I will have to restart the DB as a last resort, but I am not sure if that will solve the problem either.

its a very verbose mail, so if it noisy, kindly ignore.

else,

can you check basic connectivity from the subscriber to publisher using psql  and run a simple query ?

can you share your "create publication" and "create subscription" commands/statements too please?

i am attaching a general logical replication setup on a single server and put some scenarios where replication breaks and how to monitor and how to resume.

and how that is monitored.

postgres@controller:~$ tail db1/postgresql.conf db2/postgresql.conf

==> db1/postgresql.conf <==

# Add settings for extensions here

wal_level=logical

archive_mode = on

archive_command = '/bin/true'

max_wal_size = 48MB

min_wal_size = 32MB

shared_buffers = 32MB

port = 5001

max_logical_replication_workers = 10

==> db2/postgresql.conf <==

# Add settings for extensions here

wal_level=logical

archive_mode = on

archive_command = '/bin/true'

max_wal_size = 48MB

min_wal_size = 32MB

shared_buffers = 32MB

port = 5002

max_logical_replication_workers = 10

postgres@controller:~$ pg_ctl -D db1 -l db1.log start

waiting for server to start.... done

server started

postgres@controller:~$ pg_ctl -D db2 -l db2.log start

waiting for server to start.... done

server started

postgres@controller:~$ psql -p 5001

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# \x

Expanded display is on.

postgres=# create table t1(id int primary key);

CREATE TABLE

postgres=# create table t2(id int); -- this will throw error on delete, no replica identity

CREATE TABLE

postgres=# insert into t1 select x from generate_series(1, 100) x;

INSERT 0 100

postgres=# insert into t2 select x from generate_series(1, 100) x;

INSERT 0 100

postgres=# checkpoint;

CHECKPOINT

postgres=# \q

postgres@controller:~$ psql -p 5002

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=#  create table t1(id int primary key);

CREATE TABLE

postgres=# create table t2(id int);

CREATE TABLE

postgres=# \q

postgres@controller:~$ ps aux | grep -i postgres:

postgres    1116  0.0  0.4 113632  8232 ?        Ss   13:24   0:00 postgres: checkpointer

postgres    1117  0.0  0.2 113496  5868 ?        Ss   13:24   0:00 postgres: background writer

postgres    1118  0.0  0.3 113496  6964 ?        Ss   13:24   0:00 postgres: walwriter

postgres    1119  0.0  0.4 114032  8432 ?        Ss   13:24   0:00 postgres: autovacuum launcher

postgres    1120  0.0  0.2 113496  4132 ?        Ss   13:24   0:00 postgres: archiver

postgres    1121  0.0  0.2  72112  4896 ?        Ss   13:24   0:00 postgres: stats collector

postgres    1122  0.0  0.3 113928  6732 ?        Ss   13:24   0:00 postgres: logical replication launcher

postgres    1128  0.0  0.3 113496  5956 ?        Ss   13:24   0:00 postgres: checkpointer

postgres    1129  0.0  0.3 113496  5916 ?        Ss   13:24   0:00 postgres: background writer

postgres    1130  0.0  0.3 113496  6952 ?        Ss   13:24   0:00 postgres: walwriter

postgres    1131  0.0  0.4 114032  8384 ?        Ss   13:24   0:00 postgres: autovacuum launcher

postgres    1132  0.0  0.2 113496  4160 ?        Ss   13:24   0:00 postgres: archiver

postgres    1133  0.0  0.2  72112  4868 ?        Ss   13:24   0:00 postgres: stats collector

postgres    1134  0.0  0.3 113928  6804 ?        Ss   13:24   0:00 postgres: logical replication launcher

postgres    1186  0.0  0.0   8164   724 pts/0    S+   13:26   0:00 grep -i postgres:

postgres@controller:~$ psql -p 5001

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# create publication mypub for all tables

postgres=# create publication mypub for all tables with (publish='insert,update,delete,truncate');

CREATE PUBLICATION

postgres=# \q

postgres@controller:~$ psql -p 5002

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# create subscription mysub connection 'port=5001' publication mypub;

NOTICE:  created replication slot "mysub" on publisher

CREATE SUBSCRIPTION

postgres=# select count(1) from t1;

 count

-------

   100

(1 row)

postgres=# select count(1) from t2;

 count

-------

   100

(1 row)

postgres=# \q

postgres@controller:~$ ps aux | grep postgres:  # strace the below pids for movement

postgres    1195  0.0  0.7 114800 14744 ?        Ss   13:27   0:00 postgres: logical replication worker for subscription 16392

postgres    1196  0.0  0.7 114728 14676 ?        Ss   13:27   0:00 postgres: walsender postgres [local] START_REPLICATION

# logical replication slot is active(=t) with an active pid (which we strace) and has movement of lsn  (= healthy)

postgres@controller:~$ psql -p 5001

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# \x

Expanded display is on.

postgres=# select * from pg_replication_slots;

-[ RECORD 1 ]-------+----------

slot_name           | mysub

plugin              | pgoutput

slot_type           | logical

datoid              | 13726

database            | postgres

temporary           | f

active              | t

active_pid          | 1196

xmin                |

catalog_xmin        | 740

restart_lsn         | 0/20308F0

confirmed_flush_lsn | 0/2030928

wal_status          | reserved

safe_wal_size       |

two_phase           | f

postgres=# \q

#strace publication worker process , check if it is moving fine

root@controller:~# strace -p 1196

strace: Process 1196 attached

epoll_wait(4, [{EPOLLIN, {u32=654228920, u64=94283776310712}}], 1, 29577) = 1

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

sendto(9, "d\0\0\0\26k\0\0\0\0\2\3\t(\0\2z\27H\376\271\323\0", 23, 0, NULL, 0) = 23

epoll_wait(4, [{EPOLLIN, {u32=654228920, u64=94283776310712}}], 1, 29999) = 1

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

epoll_wait(4, [{EPOLLIN, {u32=654228920, u64=94283776310712}}], 1, 30000) = 1

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

epoll_wait(4, [{EPOLLIN, {u32=654228920, u64=94283776310712}}], 1, 30000) = 1

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

sendto(9, "d\0\0\0\26k\0\0\0\0\2\3\t(\0\2z\27J\311_\352\0", 23, 0, NULL, 0) = 23

epoll_wait(4, [{EPOLLIN, {u32=654228920, u64=94283776310712}}], 1, 29999) = 1

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

epoll_wait(4, [{EPOLLIN, {u32=654228920, u64=94283776310712}}], 1, 30000) = 1

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

epoll_wait(4, [{EPOLLIN, {u32=654228920, u64=94283776310712}}], 1, 30000) = 1

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

sendto(9, "d\0\0\0\26k\0\0\0\0\2\3\t(\0\2z\27L\224?s\0", 23, 0, NULL, 0) = 23

epoll_wait(4, [{EPOLLIN, {u32=654228920, u64=94283776310712}}], 1, 30000) = 1

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\0\0\0\2\3\t(\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

epoll_wait(4, [{EPOLLIN, {u32=654228944, u64=94283776310736}}], 1, 30000) = 1

read(10, "\27\0\0\0\0\0\0\0\0\0\0\0^\4\0\0p\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1024) = 128

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

pread64(6, "\r\321\5\0\1\0\0\0\0\0\3\2\0\0\0\0\0\3\0\0\0\0\0\0\2365\0\0\210\n\0\0"..., 8192, 196608) = 8192

stat("pg_logical/snapshots/0-2030928.snap", 0x7fff98dfb6b0) = -1 ENOENT (No such file or directory)

unlink("pg_logical/snapshots/0-2030928.snap.1196.tmp") = -1 ENOENT (No such file or directory)

openat(AT_FDCWD, "pg_logical/snapshots/0-2030928.snap.1196.tmp", O_WRONLY|O_CREAT|O_EXCL, 0600) = 7

write(7, "\1\340\241Q\346\223#\367\4\0\0\0\200\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128

fsync(7)                                = 0

close(7)                                = 0

openat(AT_FDCWD, "pg_logical/snapshots", O_RDONLY) = 7

fsync(7)                                = 0

close(7)                                = 0

rename("pg_logical/snapshots/0-2030928.snap.1196.tmp", "pg_logical/snapshots/0-2030928.snap") = 0

openat(AT_FDCWD, "pg_logical/snapshots/0-2030928.snap", O_RDWR) = 7

fsync(7)                                = 0

close(7)                                = 0

openat(AT_FDCWD, "pg_logical/snapshots", O_RDONLY) = 7

fsync(7)                                = 0

close(7)                                = 0

openat(AT_FDCWD, "pg_replslot/mysub/state.tmp", O_WRONLY|O_CREAT|O_EXCL, 0600) = 7

write(7, "\241\34\5\1W\23\376Y\2\0\0\0\270\0\0\0mysub\0\0\0\0\0\0\0\0\0\0\0"..., 200) = 200

fsync(7)                                = 0

close(7)                                = 0

rename("pg_replslot/mysub/state.tmp", "pg_replslot/mysub/state") = 0

openat(AT_FDCWD, "pg_replslot/mysub/state", O_RDWR) = 7

fsync(7)                                = 0

close(7)                                = 0

openat(AT_FDCWD, "pg_replslot/mysub", O_RDONLY) = 7

fsync(7)                                = 0

close(7)                                = 0

openat(AT_FDCWD, "pg_replslot", O_RDONLY) = 7

fsync(7)                                = 0

close(7)                                = 0

recvfrom(9, 0x7fff98dfc077, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

pread64(6, "\r\321\5\0\1\0\0\0\0\0\3\2\0\0\0\0\0\3\0\0\0\0\0\0\2365\0\0\210\n\0\0"..., 8192, 196608) = 8192

sendto(9, "d\0\0\0\26k\0\0\0\0\2\3\t`\0\2z\27M\223\336\351\0", 23, 0, NULL, 0) = 23

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\t`\0\0\0\0\2\3\t`\0\0\0\0\2\3\t`\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfc077, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

sendto(9, "d\0\0\0\26k\0\0\0\0\2\3\t\330\0\2z\27M\223\341P\0", 23, 0, NULL, 0) = 23

epoll_wait(4, [{EPOLLIN, {u32=654228920, u64=94283776310712}}], 1, 30000) = 1

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\t\330\0\0\0\0\2\3\t\330\0\0\0\0\2\3\t\330\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

epoll_wait(4, [{EPOLLIN, {u32=654228944, u64=94283776310736}}], 1, 30000) = 1

read(10, "\27\0\0\0\0\0\0\0\0\0\0\0^\4\0\0p\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1024) = 128

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

pread64(6, "\r\321\5\0\1\0\0\0\0\0\3\2\0\0\0\0\0\3\0\0\0\0\0\0\2365\0\0\210\n\0\0"..., 8192, 196608) = 8192

stat("pg_logical/snapshots/0-20309D8.snap", 0x7fff98dfb6b0) = -1 ENOENT (No such file or directory)

unlink("pg_logical/snapshots/0-20309D8.snap.1196.tmp") = -1 ENOENT (No such file or directory)

openat(AT_FDCWD, "pg_logical/snapshots/0-20309D8.snap.1196.tmp", O_WRONLY|O_CREAT|O_EXCL, 0600) = 7

write(7, "\1\340\241Q\336\33\320]\4\0\0\0\200\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128) = 128

fsync(7)                                = 0

close(7)                                = 0

openat(AT_FDCWD, "pg_logical/snapshots", O_RDONLY) = 7

fsync(7)                                = 0

close(7)                                = 0

rename("pg_logical/snapshots/0-20309D8.snap.1196.tmp", "pg_logical/snapshots/0-20309D8.snap") = 0

openat(AT_FDCWD, "pg_logical/snapshots/0-20309D8.snap", O_RDWR) = 7

fsync(7)                                = 0

close(7)                                = 0

openat(AT_FDCWD, "pg_logical/snapshots", O_RDONLY) = 7

fsync(7)                                = 0

close(7)                                = 0

openat(AT_FDCWD, "pg_replslot/mysub/state.tmp", O_WRONLY|O_CREAT|O_EXCL, 0600) = 7

write(7, "\241\34\5\1\353A\375\303\2\0\0\0\270\0\0\0mysub\0\0\0\0\0\0\0\0\0\0\0"..., 200) = 200

fsync(7)                                = 0

close(7)                                = 0

rename("pg_replslot/mysub/state.tmp", "pg_replslot/mysub/state") = 0

openat(AT_FDCWD, "pg_replslot/mysub/state", O_RDWR) = 7

fsync(7)                                = 0

close(7)                                = 0

openat(AT_FDCWD, "pg_replslot/mysub", O_RDONLY) = 7

fsync(7)                                = 0

close(7)                                = 0

openat(AT_FDCWD, "pg_replslot", O_RDONLY) = 7

fsync(7)                                = 0

close(7)                                = 0

recvfrom(9, 0x7fff98dfc077, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

sendto(9, "d\0\0\0\26k\0\0\0\0\2\3\n\20\0\2z\27M\346W\275\0", 23, 0, NULL, 0) = 23

epoll_wait(4, [{EPOLLIN, {u32=654228920, u64=94283776310712}}], 1, 24596) = 1

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\n\20\0\0\0\0\2\3\n\20\0\0\0\0\2\3\n\20\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

epoll_wait(4, [{EPOLLIN, {u32=654228944, u64=94283776310736}}], 1, 30000) = 1

read(10, "\27\0\0\0\0\0\0\0\0\0\0\0\237\5\0\0p\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1024) = 128

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

pread64(6, "\r\321\5\0\1\0\0\0\0\0\3\2\0\0\0\0\0\3\0\0\0\0\0\0\2365\0\0\210\n\0\0"..., 8192, 196608) = 8192

pread64(6, "\r\321\5\0\1\0\0\0\0 \3\2\0\0\0\0\21\10\0\0\0\0\0\0005\0\0forei"..., 8192, 204800) = 8192

recvfrom(9, 0x7fff98dfc077, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

pread64(6, "\r\321\5\0\1\0\0\0\0@\3\2\0\0\0\0U\7\0\0\0\0\0\0\0\0\0\0\0001\0\33"..., 8192, 212992) = 8192

recvfrom(9, 0x7fff98dfc077, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

pread64(6, "\r\321\5\0\1\0\0\0\0`\3\2\0\0\0\0a\16\0\0\0\0\0\0\v\30\0\337\4\0\0\203"..., 8192, 221184) = 8192

recvfrom(9, 0x7fff98dfc077, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

pread64(6, "\r\321\5\0\1\0\0\0\0\200\3\2\0\0\0\0\225\5\0\0\0\0\0\0\0\0\0\0\0>\0F"..., 8192, 229376) = 8192

sendto(9, "d\0\0\0002w\0\0\0\0\2\3\n\20\0\0\0\0\2\3\n\20\0\2z\27N]\200\371B\0"..., 51, 0, NULL, 0) = 51

brk(0x55c0270d1000)                     = 0x55c0270d1000

brk(0x55c0270ca000)                     = 0x55c0270ca000

openat(AT_FDCWD, "base/13726/3455", O_RDWR) = 7

pread64(7, "\0\0\0\0h;g\1\0\0\0\0\330\2\360\24\360\37\4 \0\0\0\0\340\237 \0\320\237 \0"..., 8192, 8192) = 8192

sendto(9, "d\0\0\0007w\0\0\0\0\2\3\233\370\0\0\0\0\2\3\233\370\0\2z\27N]\205\334C\0"..., 56, 0, NULL, 0) = 56

rt_sigprocmask(SIG_SETMASK, [URG], NULL, 8) = 0

sendto(8, "\27\0\0\0\220\0\0\0mysub\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 144, 0, NULL, 0) = 144

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\233\370\0\0\0\0\2\3\233\370\0\0\0\0\2\3\233\370\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfc077, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

epoll_wait(4, [{EPOLLIN, {u32=654228920, u64=94283776310712}}], 1, 30000) = 1

recvfrom(9, "d", 1, 0, NULL, NULL)      = 1

recvfrom(9, "\0\0\0&r\0\0\0\0\2\3\233\370\0\0\0\0\2\3\233\370\0\0\0\0\2\3\233\370\0\2z"..., 8192, 0, NULL, NULL) = 38

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

epoll_wait(4, [{EPOLLIN, {u32=654228944, u64=94283776310736}}], 1, 30000) = 1

read(10, "\27\0\0\0\0\0\0\0\0\0\0\0^\4\0\0p\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1024) = 128

recvfrom(9, 0x7fff98dfbf07, 1, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)

pread64(6, "\r\321\5\0\1\0\0\0\0\200\3\2\0\0\0\0\225\5\0\0\0\0\0\0\0\0\0\0\0>\0F"..., 8192, 229376) = 8192

stat("pg_logical/snapshots/0-2039BF8.snap", 0x7fff98dfb6b0) = -1 ENOENT (No such file or directory)

unlink("pg_logical/snapshots/0-2039BF8.snap.1196.tmp") = -1 ENOENT (No such file or directory)

openat(AT_FDCWD, "pg_logical/snapshots/0-2039BF8.snap.1196.tmp", O_WRONLY|O_CREAT|O_EXCL, 0600) = 12

write(12, "\1\340\241Q\326\370d\25\4\0\0\0\204\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 132) = 132

fsync(12)                               = 0

close(12)                               = 0

openat(AT_FDCWD, "pg_logical/snapshots", O_RDONLY) = 12

fsync(12)                               = 0

close(12)                               = 0

rename("pg_logical/snapshots/0-2039BF8.snap.1196.tmp", "pg_logical/snapshots/0-2039BF8.snap") = 0

openat(AT_FDCWD, "pg_logical/snapshots/0-2039BF8.snap", O_RDWR) = 12

fsync(12)                               = 0

close(12)                               = 0

openat(AT_FDCWD, "pg_logical/snapshots", O_RDONLY) = 12

fsync(12)                               = 0

close(12)                               = 0

openat(AT_FDCWD, "pg_replslot/mysub/state.tmp", O_WRONLY|O_CREAT|O_EXCL, 0600) = 12

write(12, "\241\34\5\1>-\275R\2\0\0\0\270\0\0\0mysub\0\0\0\0\0\0\0\0\0\0\0"..., 200) = 200

fsync(12)                               = 0

close(12)                               = 0

rename("pg_replslot/mysub/state.tmp", "pg_replslot/mysub/state") = 0

openat(AT_FDCWD, "pg_replslot/mysub/state", O_RDWR) = 12

fsync(12)                               = 0

close(12)                               = 0

openat(AT_FDCWD, "pg_replslot/mysub", O_RDONLY) = 12

fsync(12)                               = 0

close(12)                               = 0

openat(AT_FDCWD, "pg_replslot", O_RDONLY) = 12

fsync(12)                               = 0

close(12)                               = 0

openat(AT_FDCWD, "pg_replslot/mysub/state.tmp", O_WRONLY|O_CREAT|O_EXCL, 0600) = 12

write(12, "\241\34\5\1\237\331q|\2\0\0\0\270\0\0\0mysub\0\0\0\0\0\0\0\0\0\0\0"..., 200) = 200

fsync(12)                               = 0

close(12)                               = 0

rename("pg_replslot/mysub/state.tmp", "pg_replslot/mysub/state") = 0

openat(AT_FDCWD, "pg_replslot/mysub/state", O_RDWR) = 12

fsync(12)                               = 0

close(12)                               = 0

openat(AT_FDCWD, "pg_replslot/mysub", O_RDONLY) = 12

fsync(12)                               = 0

close(12)                               = 0

openat(AT_FDCWD, "pg_replslot", O_RDONLY) = 12

fsync(12)                               = 0

close(12)                               = 0

#check the subscription worker strace similarly 

strace -p 1195

# check the state og subscription

postgres@controller:~$ psql -p 5002

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# \x

Expanded display is on.

postgres=# select * from pg_subscription_rel;

-[ RECORD 1 ]---------

srsubid    | 16392

srrelid    | 16389

srsubstate | r

srsublsn   | 0/20308F0

-[ RECORD 2 ]---------

srsubid    | 16392

srrelid    | 16384

srsubstate | r

srsublsn   | 0/2030928

postgres=# select * from pg_stat_subscription;

-[ RECORD 1 ]---------+---------------------------------

subid                 | 16392

subname               | mysub

pid                   | 1195

relid                 |

received_lsn          | 0/2030928

last_msg_send_time    | 2022-02-03 13:30:10.969066+05:30

last_msg_receipt_time | 2022-02-03 13:30:10.971322+05:30

latest_end_lsn        | 0/2030928

latest_end_time       | 2022-02-03 13:30:10.969066+05:30

postgres=# \q

postgres@controller:~$ psql -p 5001

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# \x

Expanded display is on.

postgres=# select * from pg_stat_replication;

-[ RECORD 1 ]----+---------------------------------

pid              | 1196

usesysid         | 10

usename          | postgres

application_name | mysub

client_addr      |

client_hostname  |

client_port      | -1

backend_start    | 2022-02-03 13:27:40.690802+05:30

backend_xmin     |

state            | streaming

sent_lsn         | 0/2030928

write_lsn        | 0/2030928

flush_lsn        | 0/2030928

replay_lsn       | 0/2030928

write_lag        |

flush_lag        |

replay_lag       |

sync_priority    | 0

sync_state       | async

reply_time       | 2022-02-03 13:30:41.041007+05:30

#i make ddl change which will break the subscription, as table not in sync

postgres=# alter table t2 add column col2 int default 0;

ALTER TABLE

postgres=# select * from pg_stat_replication;

-[ RECORD 1 ]----+---------------------------------

pid              | 1196

usesysid         | 10

usename          | postgres

application_name | mysub

client_addr      |

client_hostname  |

client_port      | -1

backend_start    | 2022-02-03 13:27:40.690802+05:30

backend_xmin     |

state            | streaming

sent_lsn         | 0/2039BF8

write_lsn        | 0/2039BF8

flush_lsn        | 0/2039BF8

replay_lsn       | 0/2039BF8

write_lag        | 00:00:00.001365

flush_lag        | 00:00:00.001365

replay_lag       | 00:00:00.001365

sync_priority    | 0

sync_state       | async

reply_time       | 2022-02-03 13:31:11.010197+05:30

postgres=# \q

postgres@controller:~$ psql -p 5001

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# insert into t2(id,col2) select 0,0 from generate_series(1, 100) x;

INSERT 0 100

postgres=# \q

postgres@controller:~$ psql -p 5002

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# select count(1) from t2;

 count

-------

   100   -- note this should be 200, but it did not add, so we need to check for errors

(1 row)

postgres=# \x

Expanded display is on.

postgres=# select * from pg_stat_subscription;

-[ RECORD 1 ]---------+------

subid                 | 16392

subname               | mysub

pid                   |   ----no pid, subscription is not active

relid                 |

received_lsn          |

last_msg_send_time    |

last_msg_receipt_time |

latest_end_lsn        |

latest_end_time       |

postgres@controller:~$ psql -p 5001

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# \x

Expanded display is on.

postgres=# select * from pg_stat_replication;

(0 rows)

postgres=# select * from pg_replication_slots;

-[ RECORD 1 ]-------+----------

slot_name           | mysub

plugin              | pgoutput

slot_type           | logical

datoid              | 13726

database            | postgres

temporary           | f

active              | f  -- active =f , publication broken, check logs, (strace would have exited as no process died)

active_pid          |

xmin                |

catalog_xmin        | 741

restart_lsn         | 0/2039BF8

confirmed_flush_lsn | 0/2039C30

wal_status          | reserved

safe_wal_size       |

two_phase           | f

postgres=# \q

postgres@controller:~$ tail -100 db1.log

2022-02-03 13:32:06.873 IST [1456] STATEMENT:  START_REPLICATION SLOT "mysub" LOGICAL 0/0 (proto_version '2', publication_names '"mypub"')

2022-02-03 13:32:11.890 IST [1458] LOG:  starting logical decoding for slot "mysub"

2022-02-03 13:32:11.890 IST [1458] DETAIL:  Streaming transactions committing after 0/2039C30, reading WAL from 0/2039BF8.

2022-02-03 13:32:11.890 IST [1458] STATEMENT:  START_REPLICATION SLOT "mysub" LOGICAL 0/0 (proto_version '2', publication_names '"mypub"')

2022-02-03 13:32:11.891 IST [1458] LOG:  logical decoding found consistent point at 0/2039BF8

2022-02-03 13:32:11.891 IST [1458] DETAIL:  There are no running transactions.

2022-02-03 13:32:11.891 IST [1458] STATEMENT:  START_REPLICATION SLOT "mysub" LOGICAL 0/0 (proto_version '2', publication_names '"mypub"')

2022-02-03 13:32:11.892 IST [1458] LOG:  could not send data to client: Broken pipe

2022-02-03 13:33:02.074 IST [1482] CONTEXT:  slot "mysub", output plugin "pgoutput", in the change callback, associated LSN 0/203AAD8

2022-02-03 13:33:02.074 IST [1482] STATEMENT:  START_REPLICATION SLOT "mysub" LOGICAL 0/0 (proto_version '2', publication_names '"mypub"')

postgres@controller:~$ tail -100 db2.log

2022-02-03 13:24:42.101 IST [1126] LOG:  starting PostgreSQL 14.1 (Ubuntu 14.1-2.pgdg20.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 9.3.0-17ubuntu1~20.04) 9.3.0, 64-bit

2022-02-03 13:24:42.101 IST [1126] LOG:  listening on IPv6 address "::1", port 5002

2022-02-03 13:24:42.101 IST [1126] LOG:  listening on IPv4 address "127.0.0.1", port 5002

2022-02-03 13:24:42.104 IST [1126] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5002"

2022-02-03 13:24:42.109 IST [1127] LOG:  database system was shut down at 2022-02-03 13:24:25 IST

2022-02-03 13:24:42.112 IST [1126] LOG:  database system is ready to accept connections

2022-02-03 13:27:40.690 IST [1195] LOG:  logical replication apply worker for subscription "mysub" has started

2022-02-03 13:27:40.694 IST [1197] LOG:  logical replication table synchronization worker for subscription "mysub", table "t2" has started

2022-02-03 13:27:40.704 IST [1199] LOG:  logical replication table synchronization worker for subscription "mysub", table "t1" has started

2022-02-03 13:27:40.732 IST [1197] LOG:  logical replication table synchronization worker for subscription "mysub", table "t2" has finished

2022-02-03 13:27:40.746 IST [1199] LOG:  logical replication table synchronization worker for subscription "mysub", table "t1" has finished

2022-02-03 13:31:56.830 IST [1195] ERROR:  logical replication target relation "public.t2" is missing replicated column: "col2"

2022-02-03 13:31:56.831 IST [1126] LOG:  background worker "logical replication worker" (PID 1195) exited with exit code 1

postgres@controller:~$ psql -p 5002

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# alter table t2 add column col2 int default 0;

ALTER TABLE

postgres=# \q

postgres@controller:~$ tail -10 db2.log

2022-02-03 13:33:27.156 IST [1495] LOG:  logical replication apply worker for subscription "mysub" has started

2022-02-03 13:33:27.164 IST [1495] ERROR:  logical replication target relation "public.t2" is missing replicated column: "col2"

2022-02-03 13:33:27.165 IST [1126] LOG:  background worker "logical replication worker" (PID 1495) exited with exit code 1

2022-02-03 13:33:32.175 IST [1497] LOG:  logical replication apply worker for subscription "mysub" has started

2022-02-03 13:33:32.182 IST [1497] ERROR:  logical replication target relation "public.t2" is missing replicated column: "col2"

2022-02-03 13:33:32.183 IST [1126] LOG:  background worker "logical replication worker" (PID 1497) exited with exit code 1

2022-02-03 13:33:37.194 IST [1502] LOG:  logical replication apply worker for subscription "mysub" has started

2022-02-03 13:33:37.201 IST [1502] ERROR:  logical replication target relation "public.t2" is missing replicated column: "col2"

2022-02-03 13:33:37.202 IST [1126] LOG:  background worker "logical replication worker" (PID 1502) exited with exit code 1

2022-02-03 13:33:42.212 IST [1504] LOG:  logical replication apply worker for subscription "mysub" has started

postgres@controller:~$ psql -p 5002

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# \x

Expanded display is on.

postgres=# select * from pg_subscription_rel;

-[ RECORD 1 ]---------

srsubid    | 16392

srrelid    | 16389

srsubstate | r

srsublsn   | 0/20308F0

-[ RECORD 2 ]---------

srsubid    | 16392

srrelid    | 16384

srsubstate | r

srsublsn   | 0/2030928

postgres=# select * from pg_stat_subscription;

-[ RECORD 1 ]---------+---------------------------------

subid                 | 16392

subname               | mysub

pid                   | 1504

relid                 |

received_lsn          | 0/2040490

last_msg_send_time    | 2022-02-03 13:33:42.235423+05:30

last_msg_receipt_time | 2022-02-03 13:33:42.235432+05:30

latest_end_lsn        | 0/2040490

latest_end_time       | 2022-02-03 13:33:42.235423+05:30

postgres=# \q

postgres@controller:~$ psql -p 5002

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# select count(1) from t2;

 count

-------

   200

(1 row)

postgres=# \q

postgres@controller:~$ ps aux | grep postgres:    # we need to strace the below new pids/process , as old ones were terminated

postgres    1504  0.0  0.7 114904 14972 ?        Ss   13:33   0:00 postgres: logical replication worker for subscription 16392

postgres    1505  0.0  0.8 114864 15952 ?        Ss   13:33   0:00 postgres: walsender postgres [local] START_REPLICATION

postgres    1513  0.0  0.0   8160   672 pts/0    S+   13:34   0:00 grep postgres:

# check everything should be working.

postgres@controller:~$ psql -p 5001

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# delete from t2;  -- as said earlier, delete would fail, needs a fix

ERROR:  cannot delete from table "t2" because it does not have a replica identity and publishes deletes

HINT:  To enable deleting from the table, set REPLICA IDENTITY using ALTER TABLE.

postgres=# delete from t1;

DELETE 100

postgres=# alter table t2 replica identity full;  -- since no primary key or unique key

ALTER TABLE

postgres=# delete from t2;

DELETE 200

postgres=# select count(1) from t2;

 count

-------

     0

(1 row)

postgres=# select count(1) from t1;

 count

-------

     0

(1 row)

postgres=# \q

postgres@controller:~$ psql -p 5002

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# select count(1) from t1;

 count

-------

     0

(1 row)

postgres=# select count(1) from t2;

 count

-------

     0

(1 row)

so in short,

share your

from publisher

select * from pg_replication_slots;

select * from pg_stat_replication;

select * from pg_stat_activity;

ps aux | grep postgres:    # ( publisher)

from subscriber

select * from pg_stat_subscription;

select * from pg_subscription_rel;

ps aux | grep postgres:   # ( subscriber)

and logs of publisher and subscriber db (for errors, it there are no pids for above, logs should show errors)

 

trimming the email, to avoid noise.

I spent a lot of time trying multiple options/combinations and finally managed to replicate your debug output.

this is when i have , 

postgres=# show max_logical_replication_workers;

 max_logical_replication_workers

---------------------------------

 2

(1 row)

on publisher

postgres@controller:~$ psql -p 5001

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# create table t_bytea(id int primary key, somebytea bytea);

CREATE TABLE

postgres=# create table t1(id int);

CREATE TABLE

postgres=# create table t2(id int);

CREATE TABLE

postgres=# create table t3(id int);

CREATE TABLE

postgres=# create publication mypub1 for table t1;

CREATE PUBLICATION

postgres=# create publication mypub2 for table t2;

CREATE PUBLICATION

postgres=# create publication mypub3 for table t3;

CREATE PUBLICATION

postgres=# create publication mypub4 for table t3;

CREATE PUBLICATION

postgres=# create publication mypub5 for table t_bytea;

CREATE PUBLICATION

postgres=# insert into t_bytea  select x,repeat(repeat('xxx', 100), 1000)::bytea from generate_series(1, 1000) x;

INSERT 0 1000

on subscriber

postgres@controller:~$ psql -p 5002

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# create table t_bytea(id int primary key, somebytea bytea);

CREATE TABLE

postgres=#  create table t1(id int);

CREATE TABLE

postgres=#  create table t2(id int);

CREATE TABLE

postgres=#  create table t3(id int);

CREATE TABLE

postgres=#  create table t4(id int);

CREATE TABLE

postgres=#  create table t5(id int);

CREATE TABLE

postgres=# create subscription mysub1 connection 'port=5001' publication mypub1;

NOTICE:  created replication slot "mysub1" on publisher

CREATE SUBSCRIPTION

postgres=# create subscription mysub2 connection 'port=5001' publication mypub2;

NOTICE:  created replication slot "mysub2" on publisher

CREATE SUBSCRIPTION

postgres=# create subscription mysub3 connection 'port=5001' publication mypub3;

NOTICE:  created replication slot "mysub3" on publisher

CREATE SUBSCRIPTION

postgres=# create subscription mysub4 connection 'port=5001' publication mypub4;

NOTICE:  created replication slot "mysub4" on publisher

CREATE SUBSCRIPTION

postgres=# create subscription mysub5 connection 'port=5001' publication mypub5;

NOTICE:  created replication slot "mysub5" on publisher

CREATE SUBSCRIPTION

postgres=# select count(1) from t_bytea;

 count

-------

     0

(1 row)

postgres=# table pg_subscription_rel;

 srsubid | srrelid | srsubstate | srsublsn

---------+---------+------------+-----------

   16406 |   16391 | r          | 0/1722838

   16407 |   16394 | i          |

   16408 |   16397 | i          |

   16409 |   16397 | i          |

   16410 |   16384 | i          |

(5 rows)

# as expected no data in t_bytea (as it could not get any worker)

postgres=# select count(1) from t_bytea;

 count

-------

     0

(1 row)

but logs clearly state the problem

2022-02-03 23:18:31.107 IST [3430] LOG:  logical replication table synchronization worker for subscription "mysub1", table "t1" has started

2022-02-03 23:18:31.138 IST [3430] LOG:  logical replication table synchronization worker for subscription "mysub1", table "t1" has finished

2022-02-03 23:18:40.730 IST [3433] LOG:  logical replication apply worker for subscription "mysub2" has started

2022-02-03 23:18:40.737 IST [3433] WARNING:  out of logical replication worker slots

2022-02-03 23:18:40.737 IST [3433] HINT:  You might need to increase max_logical_replication_workers.

2022-02-03 23:18:45.865 IST [3433] WARNING:  out of logical replication worker slots

#publisher logs

2022-02-03 23:18:31.096 IST [3427] STATEMENT:  CREATE_REPLICATION_SLOT "mysub1" LOGICAL pgoutput NOEXPORT_SNAPSHOT

2022-02-03 23:18:31.106 IST [3429] LOG:  starting logical decoding for slot "mysub1"

2022-02-03 23:18:31.106 IST [3429] DETAIL:  Streaming transactions committing after 0/1722800, reading WAL from 0/17227C8.

2022-02-03 23:18:31.106 IST [3429] STATEMENT:  START_REPLICATION SLOT "mysub1" LOGICAL 0/0 (proto_version '2', publication_names '"mypub1"')

2022-02-03 23:18:31.106 IST [3429] LOG:  logical decoding found consistent point at 0/17227C8

2022-02-03 23:18:31.106 IST [3429] DETAIL:  There are no running transactions.

2022-02-03 23:18:31.106 IST [3429] STATEMENT:  START_REPLICATION SLOT "mysub1" LOGICAL 0/0 (proto_version '2', publication_names '"mypub1"')

2022-02-03 23:18:31.129 IST [3431] LOG:  logical decoding found consistent point at 0/1722800

2022-02-03 23:18:31.129 IST [3431] DETAIL:  There are no running transactions.

2022-02-03 23:18:31.129 IST [3431] STATEMENT:  CREATE_REPLICATION_SLOT "pg_16406_sync_16391_7060540926182153512" LOGICAL pgoutput USE_SNAPSHOT

2022-02-03 23:18:31.135 IST [3431] LOG:  starting logical decoding for slot "pg_16406_sync_16391_7060540926182153512"

2022-02-03 23:18:31.135 IST [3431] DETAIL:  Streaming transactions committing after 0/1722838, reading WAL from 0/1722800.

2022-02-03 23:18:31.135 IST [3431] STATEMENT:  START_REPLICATION SLOT "pg_16406_sync_16391_7060540926182153512" LOGICAL 0/1722838 (proto_version '2', publication_names '"mypub1"')

2022-02-03 23:18:35.718 IST [3432] LOG:  logical decoding found consistent point at 0/1722838

2022-02-03 23:18:35.718 IST [3432] DETAIL:  There are no running transactions.

2022-02-03 23:18:35.718 IST [3432] STATEMENT:  CREATE_REPLICATION_SLOT "mysub2" LOGICAL pgoutput NOEXPORT_SNAPSHOT

2022-02-03 23:18:40.737 IST [3434] LOG:  starting logical decoding for slot "mysub2"

2022-02-03 23:18:40.737 IST [3434] DETAIL:  Streaming transactions committing after 0/1722870, reading WAL from 0/1722838.

2022-02-03 23:18:40.737 IST [3434] STATEMENT:  START_REPLICATION SLOT "mysub2" LOGICAL 0/0 (proto_version '2', publication_names '"mypub2"')

2022-02-03 23:18:40.737 IST [3434] LOG:  logical decoding found consistent point at 0/1722838

2022-02-03 23:18:40.737 IST [3434] DETAIL:  There are no running transactions.

2022-02-03 23:18:40.737 IST [3434] STATEMENT:  START_REPLICATION SLOT "mysub2" LOGICAL 0/0 (proto_version '2', publication_names '"mypub2"')

2022-02-03 23:18:40.857 IST [3435] LOG:  logical decoding found consistent point at 0/1722870

2022-02-03 23:18:40.857 IST [3435] DETAIL:  There are no running transactions.

2022-02-03 23:18:40.857 IST [3435] STATEMENT:  CREATE_REPLICATION_SLOT "mysub3" LOGICAL pgoutput NOEXPORT_SNAPSHOT

2022-02-03 23:18:46.091 IST [3437] LOG:  logical decoding found consistent point at 0/17228A8

2022-02-03 23:18:46.091 IST [3437] DETAIL:  There are no running transactions.

2022-02-03 23:18:46.091 IST [3437] STATEMENT:  CREATE_REPLICATION_SLOT "mysub4" LOGICAL pgoutput NOEXPORT_SNAPSHOT

2022-02-03 23:18:51.941 IST [3439] LOG:  logical decoding found consistent point at 0/17228E0

2022-02-03 23:18:51.941 IST [3439] DETAIL:  There are no running transactions.

2022-02-03 23:18:51.941 IST [3439] STATEMENT:  CREATE_REPLICATION_SLOT "mysub5" LOGICAL pgoutput NOEXPORT_SNAPSHOT

# solution

so i bump the  max_logical_replication_workers = 10 and restart the db servers.

as there are workers available, replication catches up and tables in sync.

# on subscriber

psql (14.1 (Ubuntu 14.1-2.pgdg20.04+1))

Type "help" for help.

postgres=# select count(1) from t_bytea;

 count

-------

     0

(1 row)

postgres=# table pg_subscription_rel;

 srsubid | srrelid | srsubstate | srsublsn

---------+---------+------------+-----------

   16406 |   16391 | r          | 0/1722838

   16407 |   16394 | r          | 0/2000110

   16408 |   16397 | r          | 0/2000148

   16409 |   16397 | r          | 0/2000148

   16410 |   16384 | r          | 0/20001B8

(5 rows)

postgres=# select count(1) from t_bytea;

 count

-------

  1000

(1 row)

so two things,

can you check logs for warning messages  of out of  logical replication worker slots on subscribers ?

can you try bumping them, and check if it catches up (srsubstate should either be r(READY) or d (INITIAL COPY))

 

also monitor logs for both publisher and subscriber.

I also figured out all the debugging steps I requested earlier were useless. 

--

Thanks,

Vijay

LinkedIn - Vijaykumar Jain