Logged statement apparently did not commited...

Hello Everyone,

I would like to kindly ask for your help regarding a strange situation I meet yesterday. It might not be a postgres issue but I run out of ideas on what to test or check and so far I could not reproduce the behavior.

I have 2 (master - slave) postgres 9.0.3 databases running on SLES 11 PATCHLEVEL 1 (x86_64). For the slave I am using a statement based replication (terracotta)...

I have a cron that runs at 1:00am and checks if the dbs are in sync (it exports the data on a text file and makes a diff on the files generated on the 2 dbs).

2 days ago I've got differences for a table and I started to investigate the problem.

Postgres log is enabled on both dbs and I could compare the statements. The same statements appear in postgres log on both dbs in the same order, no errors or weird stuff. So the dbs should be in sync.

That table holds temporary information for an item. So there are inserts and updates on that table for an item (key1) and whenever that item expires all the data for that item gets deleted:

insert into mytable (key1, key2, keyval) values (1019, 1, 50);
insert into mytable (key1, key2, keyval) values (1019, 2, 100);
insert into mytable (key1, key2, keyval) values (1019, 3, 10);
update mytable set keyval = 51 where key1 =1019 and key2 = 1;
update mytable set keyval = 102 where key1 =1019 and key2 = 2;
insert into mytable (key1, key2, keyval) values (1019, 4, 10);
...
delete from mytable where key1 = 1019;

From the script that compares the 2 dbs it looks like the delete statement for a particular item did not commited on the slave. On the master there were no records for the item with key1 = 1019 but on db2 there were all the records generated by the insert and update statements....(I did extracted the insert and update statement from the log and it is exactly what the difference is). So it looks pretty clear that the delete did not commited on the slave. The delete statement appears in postgres log with begin and commit transaction and no errors.

The autovacuum is on and it gives a little information on what happened between 2 autovacuums:

before autovacuum there are 19 records in the key table for key1= 1019

first autovacuum:
2011-02-16 13:12:41.088 CST,,,10691,,4d5c21a9.29c3,1,,2011-02-16 13:12:41 CST,5/9551,0,LOG,00000,"automatic vacuum of table ""..."": index scans: 1
pages: 0 removed, 1 remain
tuples: 65 removed, 19 remain

between the autovacuums there are:

14 inserts for key1 = 1019
47 updates for key1 = 1019

25 inserts for key1 = 1021
98 updates for key1 = 1021

33 records deleted for key1 = 1019

the second autovacuum:
2011-02-16 13:52:20.358 CST,,,10868,,4d5c2af4.2a74,1,,2011-02-16 13:52:20 CST,5/9795,0,LOG,00000,"automatic vacuum of table ""..."": index scans: 1
pages: 0 removed, 2 remain
tuples: 98 removed, 58 remain

It looks like autovacuum only removed the dead tuples generated by the 98 updates on key 1021 and none of the dead tuples generated by the update and delete on item 1019...

Can this be on any help? Does anyone have an idea where else to look for clues?

Thank you for your time,
Ioana