Thread: Deferrable constraint trigger

Deferrable constraint trigger

From

Maciej Kołuda

Date:

25 January 2018, 23:19:20

Hi All,

I am trying to write constraint trigger to assure that at any given point of time I have an exactly one record "active" based on the time.

To give you some background I would like to have an exactly one box per owner active in which items will be added.

Part of the model looks like below:

CREATE TABLE boxes (

id bigint NOT NULL,

inserted_at timestamp without time zone NOT NULL,

validity_time timestamp without time zone,

version integer,

owner_id bigint NOT NULL

);

ALTER TABLE ONLY boxes ADD CONSTRAINT owners_fk FOREIGN KEY (owner_id) REFERENCES owners(id)

CREATE TABLE box_items (

box_id bigint NOT NULL,

item_id bigint NOT NULL

);

And trigger itself:

CREATE OR REPLACE FUNCTION check_active_box() RETURNS trigger AS $check_active_box$

BEGIN

IF (select count(*) from boxes where owner_id = NEW.owner_id and validity_time >= now()) > 1 THEN

RAISE EXCEPTION 'At least one valid box exists';

END IF;

RETURN NEW;

END;

$check_active_box$ LANGUAGE plpgsql;

CREATE CONSTRAINT TRIGGER check_active_box AFTER INSERT OR UPDATE ON boxes DEFERRABLE INITIALLY DEFERRED FOR EACH ROW EXECUTE PROCEDURE check_active_box();

When I try to perform simple test using two psql consoles:

BEGIN;

insert into boxes (id, inserted_at, validity_time, version, owner_id) values (1, now(), '2018-01-26 13:02:23.06', 0,10);

COMMIT;

BEGIN;

insert into boxes (id, inserted_at, validity_time, version, owner_id) values (2, now(), '2018-01-26 13:02:23.099', 0,10);

here I am getting expected error.

So everything seems to work fine

However, when running it in real application where boxes are created in concurrent manner it happens that more than one box is created.

select * from boxes;

id | inserted_at | validity_time | version | owner_id

------+-------------------------+-------------------------+---------+-----------------

5082 | 2018-01-25 15:10:09.245 | 2018-01-26 15:10:09.244 | 0 | 10

5080 | 2018-01-25 15:10:09.244 | 2018-01-26 15:10:09.231 | 0 | 10

(2 rows)

Here is the part of the pg_log:

2018-01-25 15:10:08 CET [15256-666] myuser@db LOG: execute <unnamed>: SELECT 1

2018-01-25 15:10:08 CET [15256-667] myuser@db LOG: execute <unnamed>: BEGIN

2018-01-25 15:10:08 CET [15256-668] myuser@db LOG: execute <unnamed>: select nextval ('hibernate_sequence')

2018-01-25 15:10:09 CET [15255-2] myuser@db LOG: execute <unnamed>: SELECT 1

2018-01-25 15:10:09 CET [15255-3] myuser@db LOG: execute <unnamed>: BEGIN

...

2018-01-25 15:10:09 CET [15254-2] myuser@db LOG: execute <unnamed>: SELECT 1

2018-01-25 15:10:09 CET [15254-3] myuser@db LOG: execute <unnamed>: BEGIN

....

2018-01-25 15:10:09 CET [15254-10] myuser@db LOG: execute <unnamed>: insert into boxes (inserted_at, owner_id, validity_time, version, id) values ($1, $2, $3, $4, $5)

2018-01-25 15:10:09 CET [15254-11] myuser@db DETAIL: parameters: $1 = '2018-01-25 15:10:09.245', $2 = '10', $3 = '2018-01-26 15:10:09.244', $4 = '0', $5 = '5082'

2018-01-25 15:10:09 CET [15256-676] myuser@db LOG: execute <unnamed>: insert into boxes (inserted_at, owner_id, validity_time, version, id) values ($1, $2, $3, $4, $5)

2018-01-25 15:10:09 CET [15256-677] myuser@db DETAIL: parameters: $1 = '2018-01-25 15:10:09.244', $2 = '10', $3 = '2018-01-26 15:10:09.231', $4 = '0', $5 = '5080'

2018-01-25 15:10:09 CET [15254-12] myuser@db LOG: execute <unnamed>: insert into box_messages (box_id, item_id) values ($1, $2)

2018-01-25 15:10:09 CET [15254-13] myuser@db DETAIL: parameters: $1 = '5082', $2 = '5072'

2018-01-25 15:10:09 CET [15255-10] myuser@db LOG: execute <unnamed>: insert into boxes (inserted_at, owner_id, validity_time, version, id) values ($1, $2, $3, $4, $5)

2018-01-25 15:10:09 CET [15255-11] myuser@db DETAIL: parameters: $1 = '2018-01-25 15:10:09.246', $2 = '10', $3 = '2018-01-26 15:10:09.232', $4 = '0', $5 = '5081'

2018-01-25 15:10:09 CET [15256-678] myuser@db LOG: execute <unnamed>: insert into box_items (box_id, item_id) values ($1, $2)

2018-01-25 15:10:09 CET [15256-679] myuser@db DETAIL: parameters: $1 = '5080', $2 = '5070'

2018-01-25 15:10:09 CET [15255-12] myuser@db LOG: execute <unnamed>: insert into box_items (box_id, item_id) values ($1, $2)

2018-01-25 15:10:09 CET [15255-13] myuser@db DETAIL: parameters: $1 = '5081', $2 = '5071'

2018-01-25 15:10:09 CET [15256-680] myuser@db LOG: execute S_2: COMMIT

2018-01-25 15:10:09 CET [15254-14] myuser@db LOG: execute S_1: COMMIT

2018-01-25 15:10:09 CET [15255-14] myuser@db LOG: execute S_1: COMMIT

2018-01-25 15:10:09 CET [15255-15] myuser@db ERROR: At least one valid box exists

2018-01-25 15:10:09 CET [15255-16] myuser@db STATEMENT: COMMIT

2018-01-25 15:10:09 CET [15255-17] myuser@db LOG: execute <unnamed>: BEGIN

If I read the above log correctly it looks like the last transaction box id = 5081 has been rolled back properly, but the previous one

(2018-01-25 15:10:09 CET [15254-14] myuser@db LOG: execute S_1: COMMIT) has been commited without raising en error which results in creating second unwanted box.

Could you point what possibly might be wrong with proposed constraint trigger?

Regards,

Maciej

Re: Deferrable constraint trigger

From

Laurenz Albe

Date:

26 January 2018, 15:33:08

Maciej Kołuda wrote:
> I am trying to write constraint trigger to assure that at any given point of time I have an exactly one record
"active"based on the time.
 
> To give you some background I would like to have an exactly one box per owner active in which items will be added.
> 
> And trigger itself:
> 
> CREATE OR REPLACE FUNCTION check_active_box() RETURNS trigger AS $check_active_box$
>     BEGIN
>         IF (select count(*) from boxes where owner_id = NEW.owner_id and validity_time >= now()) > 1 THEN
>             RAISE EXCEPTION 'At least one valid box exists';
>         END IF;
>         RETURN NEW;
>     END;
> $check_active_box$ LANGUAGE plpgsql;
> 
> CREATE CONSTRAINT TRIGGER check_active_box AFTER INSERT OR UPDATE ON boxes DEFERRABLE INITIALLY DEFERRED FOR EACH ROW
EXECUTEPROCEDURE check_active_box();
 
> 
> Here is the part of the pg_log:
> 
> 2018-01-25 15:10:08 CET [15256-666] myuser@db LOG:  execute <unnamed>: SELECT 1
> 2018-01-25 15:10:08 CET [15256-667] myuser@db LOG:  execute <unnamed>: BEGIN
> 2018-01-25 15:10:08 CET [15256-668] myuser@db LOG:  execute <unnamed>: select nextval ('hibernate_sequence')
> 2018-01-25 15:10:09 CET [15255-2] myuser@db LOG:  execute <unnamed>: SELECT 1
> 2018-01-25 15:10:09 CET [15255-3] myuser@db LOG:  execute <unnamed>: BEGIN
> ...
> 2018-01-25 15:10:09 CET [15254-2] myuser@db LOG:  execute <unnamed>: SELECT 1
> 2018-01-25 15:10:09 CET [15254-3] myuser@db LOG:  execute <unnamed>: BEGIN
> ....
> 2018-01-25 15:10:09 CET [15254-10] myuser@db LOG:  execute <unnamed>: insert into boxes (inserted_at, owner_id,
validity_time,version, id) values ($1, $2, $3, $4, $5)
 
> 2018-01-25 15:10:09 CET [15254-11] myuser@db DETAIL:  parameters: $1 = '2018-01-25 15:10:09.245', $2 = '10', $3 =
'2018-01-2615:10:09.244', $4 = '0', $5 = '5082'
 
> 2018-01-25 15:10:09 CET [15256-676] myuser@db LOG:  execute <unnamed>: insert into boxes (inserted_at, owner_id,
validity_time,version, id) values ($1, $2, $3, $4, $5)
 
> 2018-01-25 15:10:09 CET [15256-677] myuser@db DETAIL:  parameters: $1 = '2018-01-25 15:10:09.244', $2 = '10', $3 =
'2018-01-2615:10:09.231', $4 = '0', $5 = '5080'
 
> 2018-01-25 15:10:09 CET [15254-12] myuser@db LOG:  execute <unnamed>: insert into box_messages (box_id, item_id)
values($1, $2)
 
> 2018-01-25 15:10:09 CET [15254-13] myuser@db DETAIL:  parameters: $1 = '5082', $2 = '5072'
> 2018-01-25 15:10:09 CET [15255-10] myuser@db LOG:  execute <unnamed>: insert into boxes (inserted_at, owner_id,
validity_time,version, id) values ($1, $2, $3, $4, $5)
 
> 2018-01-25 15:10:09 CET [15255-11] myuser@db DETAIL:  parameters: $1 = '2018-01-25 15:10:09.246', $2 = '10', $3 =
'2018-01-2615:10:09.232', $4 = '0', $5 = '5081'
 
> 2018-01-25 15:10:09 CET [15256-678] myuser@db LOG:  execute <unnamed>: insert into box_items (box_id, item_id) values
($1,$2)
 
> 2018-01-25 15:10:09 CET [15256-679] myuser@db DETAIL:  parameters: $1 = '5080', $2 = '5070'
> 2018-01-25 15:10:09 CET [15255-12] myuser@db LOG:  execute <unnamed>: insert into box_items (box_id, item_id) values
($1,$2)
 
> 2018-01-25 15:10:09 CET [15255-13] myuser@db DETAIL:  parameters: $1 = '5081', $2 = '5071'
> 2018-01-25 15:10:09 CET [15256-680] myuser@db LOG:  execute S_2: COMMIT
> 2018-01-25 15:10:09 CET [15254-14] myuser@db LOG:  execute S_1: COMMIT
> 2018-01-25 15:10:09 CET [15255-14] myuser@db LOG:  execute S_1: COMMIT
> 2018-01-25 15:10:09 CET [15255-15] myuser@db ERROR:  At least one valid box exists
> 2018-01-25 15:10:09 CET [15255-16] myuser@db STATEMENT:  COMMIT
> 2018-01-25 15:10:09 CET [15255-17] myuser@db LOG:  execute <unnamed>: BEGIN
> 
> If I read the above log correctly it looks like the last transaction box id = 5081 has been rolled back properly, but
theprevious one 
 
> (2018-01-25 15:10:09 CET [15254-14] myuser@db LOG:  execute S_1: COMMIT) has been commited without raising en error
whichresults in creating second unwanted box.
 
> 
> Could you point what possibly might be wrong with proposed constraint trigger?

There is a race condition.

The trigger runs right before the transaction commits, but if both 15256 and 15254 commit
at the same time, the trigger functions may run concurrently and then both won't see the
results of the other transaction, which has not yet committed.

The window for the race condition grows with the run time of your trigger function,
but it will never go away.

You could make your function faster if you use
   IF EXISTS (SELECT 1 FROM boxes WHERE ...) THEN

Using SERIALIZABLE transactions would be a simple way to make sure your constraint is
not violated.

Yours,
Laurenz Albe