Christopher Browne cbbrowne at ca.afilias.info
Tue Jun 12 08:54:34 PDT 2007
There still seem to be some problems with the SYNC ID handling with log
shipping.

Attached is a sample:

tar tfvj
/tmp/logshipsample.tar.bz2                                               
-rw-r--r-- cbbrowne/users 124484 2007-06-12 15:18 logship_dump.sql
drwxr-xr-x cbbrowne/users      0 2007-06-12 15:33 archive_logs_2/
-rw-r--r-- cbbrowne/users 230937 2007-06-12 15:18
archive_logs_2/slony1_log_1_00000000000000000023.sql
-rw-r--r-- cbbrowne/users    574 2007-06-12 15:18
archive_logs_2/slony1_log_1_00000000000000000024.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:18
archive_logs_2/slony1_log_1_00000000000000000025.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:18
archive_logs_2/slony1_log_1_00000000000000000026.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:18
archive_logs_2/slony1_log_1_00000000000000000027.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:18
archive_logs_2/slony1_log_1_00000000000000000028.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:19
archive_logs_2/slony1_log_1_00000000000000000029.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:19
archive_logs_2/slony1_log_1_00000000000000000030.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:19
archive_logs_2/slony1_log_1_00000000000000000031.sql
-rw-r--r-- cbbrowne/users    574 2007-06-12 15:19
archive_logs_2/slony1_log_1_00000000000000000032.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:19
archive_logs_2/slony1_log_1_00000000000000000033.sql
-rw-r--r-- cbbrowne/users    574 2007-06-12 15:19
archive_logs_2/slony1_log_1_00000000000000000034.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:20
archive_logs_2/slony1_log_1_00000000000000000035.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:20
archive_logs_2/slony1_log_1_00000000000000000036.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:20
archive_logs_2/slony1_log_1_00000000000000000037.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:20
archive_logs_2/slony1_log_1_00000000000000000038.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:20
archive_logs_2/slony1_log_1_00000000000000000039.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:21
archive_logs_2/slony1_log_1_00000000000000000040.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:21
archive_logs_2/slony1_log_1_00000000000000000041.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:21
archive_logs_2/slony1_log_1_00000000000000000042.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:21
archive_logs_2/slony1_log_1_00000000000000000043.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:21
archive_logs_2/slony1_log_1_00000000000000000044.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:21
archive_logs_2/slony1_log_1_00000000000000000045.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:21
archive_logs_2/slony1_log_1_00000000000000000046.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000047.sql
-rw-r--r-- cbbrowne/users 106699 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000048.sql
-rw-r--r-- cbbrowne/users  70512 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000049.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000050.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000051.sql
-rw-r--r-- cbbrowne/users    592 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000052.sql
-rw-r--r-- cbbrowne/users    592 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000053.sql
-rw-r--r-- cbbrowne/users    592 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000054.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000055.sql
-rw-r--r-- cbbrowne/users    775 2007-06-12 15:30
archive_logs_2/slony1_log_1_00000000000000000056.sql
-rw-r--r-- cbbrowne/users    592 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000057.sql
-rw-r--r-- cbbrowne/users    592 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000058.sql
-rw-r--r-- cbbrowne/users    573 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000059.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:22
archive_logs_2/slony1_log_1_00000000000000000060.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:23
archive_logs_2/slony1_log_1_00000000000000000061.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:23
archive_logs_2/slony1_log_1_00000000000000000062.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:23
archive_logs_2/slony1_log_1_00000000000000000063.sql
-rw-r--r-- cbbrowne/users    572 2007-06-12 15:23
archive_logs_2/slony1_log_1_00000000000000000064.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:23
archive_logs_2/slony1_log_1_00000000000000000065.sql
-rw-r--r-- cbbrowne/users    574 2007-06-12 15:23
archive_logs_2/slony1_log_1_00000000000000000066.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:24
archive_logs_2/slony1_log_1_00000000000000000067.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:24
archive_logs_2/slony1_log_1_00000000000000000068.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:24
archive_logs_2/slony1_log_1_00000000000000000069.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:24
archive_logs_2/slony1_log_1_00000000000000000070.sql
-rw-r--r-- cbbrowne/users 100296 2007-06-12 15:24
archive_logs_2/slony1_log_1_00000000000000000072.sql
-rw-r--r-- cbbrowne/users 333575 2007-06-12 15:24
archive_logs_2/slony1_log_1_00000000000000000076.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:25
archive_logs_2/slony1_log_1_00000000000000000077.sql
-rw-r--r-- cbbrowne/users    575 2007-06-12 15:25
archive_logs_2/slony1_log_1_00000000000000000078.sql
-rwxr-x--- cbbrowne/users    734 2007-06-12 15:35 init_schema.sql

- logship_dump.sql is the output of the slony1_dump.sh script
- init_schema.sql is the initial schema.

Everything goes well until log #52...  For some reason file #52 (which
represents a STORE TRIGGER request) steps backwards to SYNC #10.

cbbrowne at dba2:/tmp/slony-regress.P29121> grep "setsyncTracking_offline("
archive_logs_2/slony1_log_1_0000000000000000005*
archive_logs_2/slony1_log_1_00000000000000000050.sql:select
"_slony_regress1".setsyncTracking_offline(1, '49', '50', '2007-06-12
15:22:21.551594');
archive_logs_2/slony1_log_1_00000000000000000051.sql:select
"_slony_regress1".setsyncTracking_offline(1, '50', '51', '2007-06-12
15:22:31.608051');
archive_logs_2/slony1_log_1_00000000000000000052.sql:select
"_slony_regress1".setsyncTracking_offline(1, '10', '52', '2007-06-12
15:22:31.600417');
archive_logs_2/slony1_log_1_00000000000000000053.sql:select
"_slony_regress1".setsyncTracking_offline(1, '52', '53', '2007-06-12
15:22:31.673911');
archive_logs_2/slony1_log_1_00000000000000000054.sql:select
"_slony_regress1".setsyncTracking_offline(1, '53', '54', '2007-06-12
15:22:31.703325');
archive_logs_2/slony1_log_1_00000000000000000055.sql:select
"_slony_regress1".setsyncTracking_offline(1, '51', '55', '2007-06-12
15:22:31.734366');
archive_logs_2/slony1_log_1_00000000000000000056.sql:select
"_slony_regress1".setsyncTracking_offline(1, '55', '56', '2007-06-12
15:22:31.734366');
archive_logs_2/slony1_log_1_00000000000000000057.sql:select
"_slony_regress1".setsyncTracking_offline(1, '56', '57', '2007-06-12
15:22:31.843888');
archive_logs_2/slony1_log_1_00000000000000000058.sql:select
"_slony_regress1".setsyncTracking_offline(1, '57', '58', '2007-06-12
15:22:31.873121');
archive_logs_2/slony1_log_1_00000000000000000059.sql:select
"_slony_regress1".setsyncTracking_offline(1, '55', '59', '2007-06-12
15:22:41.6803');


There are three interesting files that have "out of sequence" SYNC ID
combinations:

1. File #52 - for a STORE TRIGGER

The "start SYNC" of 10 seems pretty wacky.

2.  File #55 - which appears to be a SYNC (with no data); jumps back to
#51 as the "start SYNC".

3.  File #59 - which again appears to be a SYNC (albeit with no data).

I'm quite proud of the test case, in some ways; here's the Slonik script
that requested the DDL change (found in file #56):

  store trigger (table id=1, trigger name='nonexistant trigger', event
node=1);
  store trigger (table id=1, trigger name='another nonexistant trigger',
event node=1);
  store trigger (table id=1, trigger name='still another nonexistant
trigger', event node=1);
  EXECUTE SCRIPT (
       SET ID = 1,
       FILENAME = '${testname}/ddl_updates.sql',
       EVENT NODE = 1
    );
  store trigger (table id=1, trigger name='late, another nonexistant
trigger', event node=1);
  store trigger (table id=1, trigger name='late, still another
nonexistant trigger', event node=1);

Yes, I was intentionally abusive in having that set of STORE TRIGGER
requests.  That it stirred up problems was the point of the exercise ;-).


More information about the Slony1-bugs mailing list