Message-ID: <5692B798.2050002@ssinger.info>
Date: Sun, 10 Jan 2016 14:57:12 -0500
From: Steve Singer <steve@ssinger.info>
User-Agent: Mozilla/5.0 (X11; Linux x86_64;
 rv:31.0) Gecko/20100101 Icedove/31.8.0
MIME-Version: 1.0
To: Petr Jelinek <petr@2ndquadrant.com>,
 PostgreSQL-development <pgsql-hackers@postgresql.org>
CC: Craig Ringer <craig@2ndquadrant.com>
Subject: Re: pglogical - logical replication contrib module
References: <5685BB86.5010901@2ndquadrant.com> <569151D5.3060003@ssinger.info>
In-Reply-To: <569151D5.3060003@ssinger.info>
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 7bit
Precedence: bulk
Sender: pgsql-hackers-owner@postgresql.org

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;
CREATE EXTENSION
test3=# select pglogical.create_node(node_name:='test3', 
dsn:='host=localhost dbname=test3 port=5436');
  create_node
-------------
   2001662995
(1 row)

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

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
_test2_defaultsub"
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/
18292D8
2016-01-10 13:03:15 EST test2DETAIL:  Logical decoding will begin using 
saved sn
apshot.
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:
http://www.postgresql.org/mailpref/pgsql-hackers