Re: Subscription stuck at initialize state

Поиск
Список
Период
Сортировка
От Vijaykumar Jain
Тема Re: Subscription stuck at initialize state
Дата
Msg-id CAM+6J949E4YGZy9TePPTzspf8u49rwuTNVQm0396u3sOGZDSqg@mail.gmail.com
обсуждение исходный текст
Ответ на Re: Subscription stuck at initialize state  (Abhishek Bhola <abhishek.bhola@japannext.co.jp>)
Ответы Re: Subscription stuck at initialize state  (Abhishek Bhola <abhishek.bhola@japannext.co.jp>)
Список pgsql-general
Дерево обсуждения


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)


 

В списке pgsql-general по дате отправления:

Предыдущее
От: Abhishek Bhola
Дата:
Сообщение: Re: Subscription stuck at initialize state
Следующее
От: Simon Riggs
Дата:
Сообщение: Re: Undetected Deadlock