I'm having trouble understanding something I saw in my data from
yesterday involving an inconsistency between values in a table and its
associated rule-updated log table.
For application debugging purposes (effectiveness of web double-submit
suppression) we have a rule that creates an entry in a log table
whenever the table we are watching is updated:
Rule:
foo_update_rule AS ON UPDATE TO foo DO
INSERT INTO foo_updatelog (old_f1, new_f1, old_f2, new_f2...)
VALUES (old.f1, new.f1, old.f2, new.f2...)
Where foo is:
Column | Type | Modifiers
----------+-----------------------------+---------------
r1 | character varying(30) |
r2 | character varying(30) |
...
And foo_updatelog is:
Column | Type | Modifiers
-----------+-----------------------------+---------------
updatetime | timestamp without time zone | default now()
old_r1 | character varying(30) |
new_r1 | character varying(30) |
...
Normally this works well to give us the info we need, but this morning I
found my table showing f1 equal to 4 and my most recent log entries
showing:
updatetime | old_f1 | new_f1
---------------------------+--------+--------
2008-11-25 17:33:45.537564 | 2 | 3
2008-11-25 17:33:45.539737 | 2 | 3
(The field f1 is a counter - the update query casts the varchar(30) to
int, adds one, and casts the result back to varchar(30) due to an
unfortunate current requirement on the application side.)
I was able to verify that this is a legitimately trapped double-submit
but I don't understand why the update log is showing a count of 2->3
twice instead of 2->3 then 3->4 like it typically would.
This database is still in 7.4.x land (I know, we're working on it) so if
it is related to a known issue I didn't find in subsequent release
notes, my apologies. I didn't find anything in the logs that would
explain it.
Any ideas?
Cheers,
Steve