Re: Odd on-update inconsistency

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

Steve Crawford wrote:
> 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:

Ah, I think you'll find you don't. You have a rule that looks at first
glance like it *should* add an entry to your log table.

Rules rewrite the query like a macro would and OLD and NEW don't refer
to a row but to the entire set of rows. The most common problems you'll
see are related to:
1. nextval() / currval() not behaving like you'd think.
2. in particular with multiple-row updates or inserts

See the mailing list archives for plenty of discussion, and I think the
current manuals have a better description of rules than there used to be.

For inserting to a log table you'll want a trigger.

--
Richard Huxton
Archonet Ltd

Richard Huxton <dev(at)archonet(dot)com> writes:
> Steve Crawford wrote:
>> 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:

> Ah, I think you'll find you don't. You have a rule that looks at first
> glance like it *should* add an entry to your log table.

We'd have to see the original query (the one the rule acted on) to be
sure, but I suspect Richard's diagnosis is correct.

> For inserting to a log table you'll want a trigger.

+1 ... triggers are way less likely to do strange things.

regards, tom lane

Richard Huxton wrote:
> Steve Crawford wrote:
>
>> 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:
>>
>
> Ah, I think you'll find you don't. You have a rule that looks at first
> glance like it *should* add an entry to your log table.
>
> Rules rewrite the query like a macro would and OLD and NEW don't refer
> to a row but to the entire set of rows. The most common problems you'll
> see are related to:
> 1. nextval() / currval() not behaving like you'd think.
> 2. in particular with multiple-row updates or inserts
>
> See the mailing list archives for plenty of discussion, and I think the
> current manuals have a better description of rules than there used to be.
>
> For inserting to a log table you'll want a trigger.
>
>
Hmmm. I was aware of certain issues with rules but in this case we have
no sequences/nextval()/currval() issues and, except for period-start
resets of certain columns, the normal update query only operates on a
single row (increment count for a given location) - and I reverified
that the key column really is unique.

It's not a big problem (this project ends in a month anyway). I just
want to increase my understanding to avoid future foot-gun potential as
I hadn't seen how our current setup would cause this type of issue. I
guess if it's critical that it works, I'll just write a trigger but
rules are quicker and easier.

Cheers,
Steve