Thread: BUG #4307: INSERT fails with primary key contraint

The following bug has been logged online:

Bug reference:      4307
Logged by:          Oskars Ozols
Email address:      oskars.ozols@gmail.com
PostgreSQL version: 8.3
Operating system:   SuSE Linux Enterprise Server
Description:        INSERT fails with primary key contraint
Details:

I have following table for event log:

CREATE TABLE event_log
(
  id bigint NOT NULL DEFAULT
nextval(('public.event_log_id_seq'::text)::regclass),
  user_id integer,
  date_time timestamp(0) without time zone,
  ip_address character varying(15) NOT NULL,
  action_type character varying(500) NOT NULL,
  severity integer NOT NULL,
  parameters text,
  web_address character varying(160),
  server character(1),
  CONSTRAINT event_log_pkey PRIMARY KEY (id)
)
WITH (OIDS=FALSE);

During high load (processor load ~95%) of different SELECT/INSERT requests
this table starts to give following errors in db log:

2008-07-15 12:32:03 EEST ERROR:  duplicate key value violates unique
constraint "event_log_pkey"
2008-07-15 12:32:03 EEST STATEMENT:  INSERT INTO public.event_log
(date_time, ip_address, action_type, severity, parameters, web_address,
server, user_id, id) VALUES ('2008-07-15 12:28:50.000000',
'123.123.123.123', 'WebServices.SomeService:LogError', 70000, 'error text',
'http://123.123.123.123/WebServices/SomeService.asmx', '4', 75, 156112)

You may notice the difference in time when message was written to db log
(12:32:04) and actual time of event (12:28:50).

Currently there are ~3 million rows in event_log. Old records are regulary
deleted (autovacuum is on, too). During high peak it's possible that 20
events are finished to be written to event_log in 1 sec.
Current Start value for sequence event_log_id_seq is 8536444.

I have noticed that during high load Postgre starts to use old free sequence
values (like 156112 in my sample). Sometimes it's ok, but sometimes it fails
with error above.

"Oskars Ozols" <oskars.ozols@gmail.com> writes:
> I have noticed that during high load Postgre starts to use old free sequence
> values (like 156112 in my sample). Sometimes it's ok, but sometimes it fails
> with error above.

This is fairly hard to believe; the sequence code was debugged years
ago.  Particularly seeing that your application is evidently supplying
the id value for itself in the INSERT (from a previous nextval, or perhaps
some other way?), it seems much more likely that there's a bug on the
application side.

If you'd like us to pursue this, please put together a self-contained
test case.  Assuming it's real, perhaps a simple custom script for
pgbench would serve to show the problem.

            regards, tom lane

"Oskars Ozols" <oskars.ozols@gmail.com> writes:

>   id bigint NOT NULL DEFAULT nextval(('public.event_log_id_seq'::text)::regclass),

> 2008-07-15 12:32:03 EEST STATEMENT:  INSERT INTO public.event_log
> (date_time, ip_address, action_type, severity, parameters, web_address,
> server, user_id, id) VALUES ('2008-07-15 12:28:50.000000',
> '123.123.123.123', 'WebServices.SomeService:LogError', 70000, 'error text',
> 'http://123.123.123.123/WebServices/SomeService.asmx', '4', 75, 156112)

There's something strange here. Your SQL statement includes the id as a
literal constant 156112. This isn't the normal way to write this query. This
is defeating the point of the DEFAULT you see in the table definition.

Postgres guarantees that the nextval() function will only return each value
once. But it's not clear from this log how your application is generating the
156112 value which it is explicitly putting in the query. If it's getting it
by calling nextval() then it's somehow using it twice.

It's also possible someone has written code to pick primary key values by
calling "select max(id)+1". That is guaranteed to have race conditions like
this.

The safest thing to do is to just leave out the id column from your INSERT
statement. Just let the DEFAULT expression generate a value for you. Then you
can use curval('event_log_id_seq') to find out what value it generated.

--
  Gregory Stark
  EnterpriseDB          http://www.enterprisedb.com
  Ask me about EnterpriseDB's RemoteDBA services!

I use NHibernate 1.2.1.4 and Npgsql 0.7.1 database driver for data
access layer. From your comments it looks like these components are
responsible for INSERT statement creation (mostly NHibernate).

I think you can close this bug and I will search for solutions in
NHibernate community.

Gregory Stark wrote:
> "Oskars Ozols" <oskars.ozols@gmail.com> writes:
>
>>   id bigint NOT NULL DEFAULT nextval(('public.event_log_id_seq'::text)::regclass),
>
>> 2008-07-15 12:32:03 EEST STATEMENT:  INSERT INTO public.event_log
>> (date_time, ip_address, action_type, severity, parameters, web_address,
>> server, user_id, id) VALUES ('2008-07-15 12:28:50.000000',
>> '123.123.123.123', 'WebServices.SomeService:LogError', 70000, 'error text',
>> 'http://123.123.123.123/WebServices/SomeService.asmx', '4', 75, 156112)
>
> There's something strange here. Your SQL statement includes the id as a
> literal constant 156112. This isn't the normal way to write this query. This
> is defeating the point of the DEFAULT you see in the table definition.
>
> Postgres guarantees that the nextval() function will only return each value
> once. But it's not clear from this log how your application is generating the
> 156112 value which it is explicitly putting in the query. If it's getting it
> by calling nextval() then it's somehow using it twice.
>
> It's also possible someone has written code to pick primary key values by
> calling "select max(id)+1". That is guaranteed to have race conditions like
> this.
>
> The safest thing to do is to just leave out the id column from your INSERT
> statement. Just let the DEFAULT expression generate a value for you. Then you
> can use curval('event_log_id_seq') to find out what value it generated.
>

--
Oskars Ozols