Deferrable constraint trigger

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(at)db LOG: execute <unnamed>:
SELECT 1
2018-01-25 15:10:08 CET [15256-667] myuser(at)db LOG: execute <unnamed>: BEGIN
2018-01-25 15:10:08 CET [15256-668] myuser(at)db LOG: execute <unnamed>:
select nextval ('hibernate_sequence')
2018-01-25 15:10:09 CET [15255-2] myuser(at)db LOG: execute <unnamed>: SELECT
1
2018-01-25 15:10:09 CET [15255-3] myuser(at)db LOG: execute <unnamed>: BEGIN
...
2018-01-25 15:10:09 CET [15254-2] myuser(at)db LOG: execute <unnamed>: SELECT
1
2018-01-25 15:10:09 CET [15254-3] myuser(at)db LOG: execute <unnamed>: BEGIN
....
2018-01-25 15:10:09 CET [15254-10] myuser(at)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(at)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(at)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(at)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(at)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(at)db DETAIL: parameters: $1 =
'5082', $2 = '5072'
2018-01-25 15:10:09 CET [15255-10] myuser(at)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(at)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(at)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(at)db DETAIL: parameters: $1 =
'5080', $2 = '5070'
2018-01-25 15:10:09 CET [15255-12] myuser(at)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(at)db DETAIL: parameters: $1 =
'5081', $2 = '5071'
2018-01-25 15:10:09 CET [15256-680] myuser(at)db LOG: execute S_2: COMMIT
2018-01-25 15:10:09 CET [15254-14] myuser(at)db LOG: execute S_1: COMMIT
2018-01-25 15:10:09 CET [15255-14] myuser(at)db LOG: execute S_1: COMMIT
2018-01-25 15:10:09 CET [15255-15] myuser(at)db ERROR: At least one valid box
exists
2018-01-25 15:10:09 CET [15255-16] myuser(at)db STATEMENT: COMMIT
2018-01-25 15:10:09 CET [15255-17] myuser(at)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(at)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