I found a couple more issues with archive logging so far. Specifically 
some related to replicating sequences (seems like this could have never 
worked).

However, I have no clue why in your case the archive log writer thinks 
that set 10 would be already on event 54, when it in fact is only on 52. 
What event types are 52, 53 and 54?


Jan

On 8/6/2007 2:39 AM, Mikko Partio wrote:
> 
> On 7/29/07, *Jan Wieck* <JanWieck at yahoo.com <mailto:JanWieck at yahoo.com>> 
> wrote:
> 
> 
> 
> 
>     This one played quite a bit hide and seek with me. But I think I found
>     and fixed the bug.
> 
>     The problem occurred when some action (like STORE_SET) caused the
>     subscriber slon to perform an internal restart. During that, the
>     current
>     setsync tracking in the pset structure is reinitialized. However, since
>     the sl_setsync table is not updated on events other than SYNC, this
>     would lead to the wrong (too low) old sync expected if the last
>     event(s)
>     processed from that node where no SYNC events.
> 
>     Thanks for the detailed example.
> 
> 
> 
> My experiments show me that the problem persists. The test-case is the 
> same as in the previous example (started from scratch):
>  
> 
>      >
>      > 1) Create databases and some tables
>      >
>      > $ createdb -D data -E utf8 test3
>      > $ psql test3
>      >
>      > test3=# create table a (id int primary key);
>      > test3=# create table b (id int primary key);
>      > test3=# create table c (id int primary key);
>      >
>      > $ createdb -T test3 test3_lo
>      > $ createdb -T test3 test3_log
>      >
>      > 2) Create the replication cluster
>      >
>      > $ cat test3_preamble.slonik
>      > cluster name = test3;
>      >
>      > node 1 admin conninfo = 'host=localhost dbname=test3 user=postgres
>      > password=xxx';
>      > node 2 admin conninfo = 'host=localhost dbname=test3_lo user=postgres
>      > password=xxx';
>      >
>      > $ cat test3_init.slonik
>      > #!/bin/sh
>      >
>      > slonik <<_EOF_
>      >
>      >         include <test3_preamble.slonik>;
>      >
>      >         init cluster (id=1, comment='original database');
>      >
>      >         store node (id=2, comment = 'dummy loopback database');
>      >         store path (server=1, client=2, conninfo='dbname=test3
>      > host=localhost user=postgres password=xxx');
>      >         store path (server=2, client=1, conninfo='dbname=test3_lo
>      > host=localhost user=postgres password=xxx');
>      >         store listen (origin=1, provider=1, receiver=2);
>      >         store listen (origin=2, provider=2, receiver=1);
>      >
>      > _EOF_
>      >
>      > $ ./test3_init.slonik
>      >
>      > $ slon test3 "dbname=test3 host=localhost user=postgres
>     password=xxx"
>      > $ slon -a /tmp/logshipping/test3 test3 "dbname=test3_lo
>     host=localhost
>      > user=postgres password=xxx"
>      >
>      > $ cat test3_create_set.slonik
>      > #!/bin/sh
>      >
>      > if [ $# -ne 3 ]; then
>      >         echo "Usage: $0 SETID TABLEID TABLENAME"
>      >         echo "Example: $0 3 17 public.x"
>      >         exit 1
>      > fi
>      >
>      > slonik <<_EOF_
>      >
>      >         include <test3_preamble.slonik>;
>      >
>      >         create set (id=$1, origin=1, comment='Set #$1');
>      >         set add table (set id = $1, origin = 1, id = $2, fully
>     qualified
>      > name = '$3');
>      >
>      > _EOF_
>      >
>      > $ ./test3_create_set.slonik 1 1 public.a
>      > $ cat test3_subscribe.slonik
>      > #!/bin/sh
>      >
>      > if [ -z $1 ]; then
>      >         echo "Usage: $0 SETID"
>      >         exit 1;
>      > fi
>      >
>      > slonik <<_EOF_
>      >
>      >         include <test3_preamble.slonik>;
>      >
>      >         subscribe set (id=$1, provider=1, receiver=2, forward=no);
>      >
>      > _EOF_
>      >
>      > $ ./test3_subscribe.slonik 1
>      > $ psql test3_lo
>      > test3_lo=# \d a
>      >        Table " public.a"
>      >  Column |  Type   | Modifiers
>      > --------+---------+-----------
>      >  id     | integer | not null
>      > Indexes:
>      >     "a_pkey" PRIMARY KEY, btree (id)
>      > Triggers:
>      >     _test3_denyaccess_1 BEFORE INSERT OR DELETE OR UPDATE ON a
>     FOR EACH
>      > ROW EXECUTE PROCEDURE _test3.denyaccess('_test3')
>      >
>      > $ psql test3
>      > test3=# insert into a select * from generate_series(1,100);
>      >
>      > 3) Dump the state of the cluster to logshipping database
>      >
>      > $ ./slony1_dump.sh test3_lo test3 | psql test3_log
>      > $ psql test3_log
>      > test3_log=# select count(*) from a;
>      >  count
>      > -------
>      >    100
>      > (1 row)
>      >
>      > 4) Insert some data to origin db and see if it gets to logshipping db
>      >
>      > test3=# insert into a select * from generate_series(101,200);
>      >
>      > $ psql -d test3_log -f
>      > /tmp/logshipping/test3/slony1_log_1_00000000000000000060.sql
>      > $ psql test3_log
>      > test3_log=# select count(*) from a;
>      >  count
>      > -------
>      >    200
>      > (1 row)
>      >
>      > 5) Create another replication set
>      >
>      > $ ./test3_create_set.slonik 10 2 public.b
>      > $ ./test3_subscribe.slonik 10
>      >
>      > 6) Start applying logfiles to logshipping db
>      >
> 
> 
> Here's the new output:
> 
> 
> $ psql -d test3_log -f slony1_log_1_00000000000000000053.sql
> START TRANSACTION
> psql:slony1_log_1_00000000000000000053.sql:6: NOTICE:  Slony-I: Process 
> set 1 sync 53 time 2007-08-06 09:30: 03.823825+03
>  setsynctracking_offline
> -------------------------
>                       53
> (1 row)
> 
> COMMIT
> VACUUM
> 
> $ psql -d test3_log -f slony1_log_1_00000000000000000054.sql
> START TRANSACTION
> psql:slony1_log_1_00000000000000000054.sql:6: NOTICE:  Slony-I: Process 
> set 1 sync 54 time 2007-08-06 09:30:03.823825+03
>  setsynctracking_offline
> -------------------------
>                       54
> (1 row)
> 
> DELETE 0
>  finishtableaftercopy
> ----------------------
>                     1
> (1 row)
> 
> ANALYZE
> INSERT 0 1
> COMMIT
> VACUUM
> 
> 
> $ psql -d test3_log -f slony1_log_1_00000000000000000055.sql
> START TRANSACTION
> psql:slony1_log_1_00000000000000000055.sql:5: NOTICE:  Slony-I: Process 
> set 1 sync 55 time 2007-08-06 09:30:10.843406+03
>  setsynctracking_offline
> -------------------------
>                       55
> (1 row)
> 
> psql:slony1_log_1_00000000000000000055.sql:11: ERROR:  Slony-I: set 10 
> is on sync 52, this archive log expects 54
> 
> 
> Here's the contents of the sync-files 54 and 55:
> 
> $ cat slony1_log_1_00000000000000000054.sql
> -- Slony-I log shipping archive
> -- Node 1, Event 54
> start transaction;
> -- ENABLE_SUBSCRIPTION
> 
> select "_test3".setsyncTracking_offline(1, '53', '54', '2007-08-06 
> 09:30:03.823825 ');
> -- end of log archiving header
> ------------------------------------------------------------------
> -- start of Slony-I data
> ------------------------------------------------------------------
> delete from "public"."b";
> copy "public"."b" ("id") from stdin;
> \.
> select "_test3".finishTableAfterCopy(2); analyze "public"."b";
> insert into "_test3".sl_setsync_offline (ssy_setid, ssy_seqno) values 
> ('10', '52');
> 
> ------------------------------------------------------------------
> -- End Of Archive Log
> ------------------------------------------------------------------
> commit;
> vacuum analyze "_test3".sl_setsync_offline;
> 
> 
> 
> $ cat slony1_log_1_00000000000000000055.sql
> -- Slony-I log shipping archive
> -- Node 1, Event 55
> start transaction;
> 
> select "_test3".setsyncTracking_offline(1, '54', '55', '2007-08-06 
> 09:30: 10.843406');
> -- end of log archiving header
> ------------------------------------------------------------------
> -- start of Slony-I data
> ------------------------------------------------------------------
> 
> select "_test3".setsyncTracking_offline(10, '54', '55', '2007-08-06 
> 09:30:10.843406');
> -- end of log archiving header
> ------------------------------------------------------------------
> -- start of Slony-I data
> ------------------------------------------------------------------
> 
> ------------------------------------------------------------------
> -- End Of Archive Log
> ------------------------------------------------------------------
> commit;
> vacuum analyze "_test3".sl_setsync_offline;
> 
> 
> 
> Here's the contents of the setsync-table:
> 
> 
> test3_log=# select * from _test3.sl_setsync_offline ;
>  ssy_setid | ssy_seqno |         ssy_synctime
> -----------+-----------+-------------------------------
>          1 |        54 | 2007-08-06 09:30:03.823825+03
>         10 |        52 |
> (2 rows)
> 
> 
> 
> $ slon -v
> slon version 1.2.11
> 
> Any more info I can provide?
> 
> Regards
> 
> Mikko
> 
> 


-- 
#======================================================================#
# It's easier to get forgiveness for being wrong than for being right. #
# Let's break this rule - forgive me.                                  #
#================================================== JanWieck at Yahoo.com #