On 01/09/2016 01:30 PM, Steve Singer wrote:
On 12/31/2015 06:34 PM, Petr Jelinek wrote:

I'm not really sure what to do to 'recover' my cluster at this point so I'll send this off and rebuild my cluster and start over.

I had a setup test1--->test2 (with 2 tables in the default set)

I then created a third database (all three hosted on the same PG cluster)

In the third database (test3)
test3=# create extension pglogical;
test3=# select pglogical.create_node(node_name:='test3', dsn:='host=localhost dbname=test3 port=5436');
(1 row)

test3=# select pglogical.create_subscription(subscription_name:='defaultsub',provider_dsn:='host=localhost dbname=test2 port=5436');

It copied the schema over but not the data (if I use test2 as the provider_dsn then it does copy the data).

I then tried inserting a row into a table on test1. Things crashed and after crash recovery I keep getting

2016-01-10 13:03:15 EST LOG:  database system is ready to accept connections
2016-01-10 13:03:15 EST LOG:  autovacuum launcher started
2016-01-10 13:03:15 EST LOG:  starting apply for subscription defaultsub
2016-01-10 13:03:15 EST LOG:  starting apply for subscription defaultsub
2016-01-10 13:03:15 EST test2LOG: starting logical decoding for slot "pgl_test3
2016-01-10 13:03:15 EST test2DETAIL: streaming transactions committing after 0/
18292D8, reading WAL from 0/18292D8
2016-01-10 13:03:15 EST test2LOG: logical decoding found consistent point at 0/
2016-01-10 13:03:15 EST test2DETAIL: Logical decoding will begin using saved sn
TRAP: FailedAssertion("!(IsTransactionState())", File: "catcache.c", Line: 1127)
2016-01-10 13:03:15 EST test2LOG:  unexpected EOF on standby connection
2016-01-10 13:03:15 EST LOG: worker process: pglogical apply 17016:2974019075 (
PID 24746) was terminated by signal 6: Aborted

The stack trace is

#3  0x00000000007b83af in SearchCatCache (cache=0xe27d18, v1=15015784,
    v2=v2@entry=0, v3=v3@entry=0, v4=v4@entry=0) at catcache.c:1127
#4  0x00000000007c503e in SearchSysCache (cacheId=cacheId@entry=47,
    key1=<optimized out>, key2=key2@entry=0, key3=key3@entry=0,
    key4=key4@entry=0) at syscache.c:981
#5  0x00000000006996d4 in replorigin_by_name (
    roname=0xe51f30 "pgl_test2_test1_defaultsub",
    missing_ok=missing_ok@entry=0 '\000') at origin.c:216
#6  0x00007fdb54a908d3 in handle_origin (s=0x7ffd873f6da0)
    at pglogical_apply.c:235
#7  replication_handler (s=0x7ffd873f6da0) at pglogical_apply.c:1031
#8 apply_work (streamConn=streamConn@entry=0xe84fb0) at pglogical_apply.c:1309
#9  0x00007fdb54a911cc in pglogical_apply_main (main_arg=<optimized out>)
    at pglogical_apply.c:1691
#10 0x0000000000674912 in StartBackgroundWorker () at bgworker.c:726
---Type <return> to continue, or q <return> to quit---
#11 0x000000000067f7e2 in do_start_bgworker (rw=0xe03890) at postmaster.c:5501
#12 maybe_start_bgworker () at postmaster.c:5676
#13 0x0000000000680206 in sigusr1_handler (postgres_signal_arg=<optimized out>)
    at postmaster.c:4937
#14 <signal handler called>
#15 0x00007fdb54fa2293 in __select_nocancel ()
    at ../sysdeps/unix/syscall-template.S:81
#16 0x0000000000468285 in ServerLoop () at postmaster.c:1648
#17 0x000000000068161e in PostmasterMain (argc=argc@entry=3,
    argv=argv@entry=0xddede0) at postmaster.c:1292
#18 0x000000000046979d in main (argc=3, argv=0xddede0) at main.c:223

I tried dropping the subscription and re-adding it.  I keep getting

2016-01-10 13:21:48 EST test1LOG: logical decoding found consistent point at 0/1830080
2016-01-10 13:21:48 EST test1DETAIL:  There are no running transactions.
2016-01-10 13:21:48 EST test1LOG: exported logical decoding snapshot: "000004DE-1" with 0 transaction IDs
2016-01-10 13:21:48 EST test3ERROR:  relation "a" already exists
2016-01-10 13:21:48 EST test3STATEMENT:  CREATE TABLE a (
        a integer NOT NULL,
        b integer

pg_restore: [archiver (db)] Error while PROCESSING TOC:
pg_restore: [archiver (db)] Error from TOC entry 182; 1259 16700 TABLE a ssinger pg_restore: [archiver (db)] could not execute query: ERROR: relation "a" already exists
    Command was: CREATE TABLE a (
    a integer NOT NULL,
    b integer

2016-01-10 13:21:48 EST ERROR: could not execute command "/usr/local/pgsql96gitlogical/bin/pg_restore --section="pre-data" --exit-on-error -1 -d "host=localhost dbname=test3 port=5436" "/tmp/pglogical-28079.dump"" 2016-01-10 13:21:48 EST test1LOG: unexpected EOF on client connection with an open transaction 2016-01-10 13:21:48 EST LOG: worker process: pglogical apply 17016:844915593 (PID 28079) exited with exit code 1 2016-01-10 13:21:48 EST ERROR: subscriber defaultsub4 initialization failed during nonrecoverable step (s), please try the setup again

Which is probably also the cause of the error I reported yesterday (that I tried creating a subscription without dropping the tables). From a usability point of view I think we need a way of making this errors available in the output of pglogical.show_subscription_status().

I asked to subscribe something through psql, even thought it is asynchronous, if the async operation fails I should be able to learn about the problem through psql. If I am writing a script to subscribe a node it needs a way in my script of checking if the subscription has failed and reporting the error.
My subscription script might not have easy access to the server log.

+- `pglogical.show_subscription_table(subscription_name name,
+  relation regclass)`
+  Shows synchronization status of a table.
+  Parameters:
+  - `subscription_name` - name of the existing subscription
+  - `relation` - name of existing table, optionally qualified

It isn't clear from the documentation what the output of this function means, nor could I tell looking at it. Is this function just supposed to tell us if a table is part of the replication set or if it is 'up-to-date'. It still reports 'synchornized' when a table is behind.

Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:

Reply via email to