Обсуждение: Drop does not always drop

I'm building a system in Smalltalk and using unit tests (SUnit)
extensively.  The unit tests cover all model and persistence aspects of
the system, and part of what they do is create and drop the tables in
the system for each bunch of tests.  So, tables are being rapidly
created and dropped.

Sometimes, the drops don't work, and I get errors when I try and create
the tables again like:

Error message: ERROR:  relation "member_member_id_seq" already exists

or:

Error message: ERROR:  duplicate key violates unique constraint
"pg_class_relname_nsp_index"

Note that if I run the *same unit tests* 10 time in a row (just hitting
the "test" button in the SUnit UI 10 times), 2 or 3 iterations of the
tests will fail with one of the above messages.  All the other tests
work as expected - the dropped tables are dropped and stay dropped.

I have a complete log of a session which demonstrates all three
situation (works, "already exists" and "duplicate key").  This log is
from the Smalltalk PostgreSQL driver and shows all the messages passed
between my Smalltalk image and the PostgreSQL backend.  I've not posted
the log here because it's 40k, but here are some snippets:

In some cases, the deletes look like this in the log (in others a
transaction is started and committed):

December 19, 2004 19:17:40.533
<<<<<    ReadyForQueryMessage

December 19, 2004 19:17:40.533
>>>>>    QueryMessage
'drop table member'

December 19, 2004 19:17:40.540
<<<<<    CompletedResponseMessage
Command tag: DROP TABLE

December 19, 2004 19:17:40.540
<<<<<    ReadyForQueryMessage

December 19, 2004 19:17:40.540
>>>>>    QueryMessage
'drop table email_address'

December 19, 2004 19:17:40.545
<<<<<    CompletedResponseMessage
Command tag: DROP TABLE

Here are two tables being created OK:

December 19, 2004 19:17:40.545
<<<<<    ReadyForQueryMessage

December 19, 2004 19:17:40.545
>>>>>    QueryMessage
'create table member (
    member_id serial primary key,
    member_number integer)'

December 19, 2004 19:17:40.546
<<<<<    NoticeResponseMessage
Message: NOTICE:  CREATE TABLE will create implicit sequence
"member_member_id_seq" for "serial" column "member.member_id"

December 19, 2004 19:17:40.546
>>>>>    QueryMessage
'create table email_address (
    email_address_id serial primary key,
    email_address_string text)'

December 19, 2004 19:17:40.547
<<<<<    NoticeResponseMessage
Message: NOTICE:  CREATE TABLE / PRIMARY KEY will create implicit index
"member_pkey" for table "member"

Here is the "already exists" (remember, this happens after an apparently
successful drop):

December 19, 2004 19:17:32.006
<<<<<    ReadyForQueryMessage

December 19, 2004 19:17:32.006
>>>>>    QueryMessage
'create table member (
    member_id serial primary key,
    member_number integer)'

December 19, 2004 19:17:32.007
<<<<<    NoticeResponseMessage
Message: NOTICE:  CREATE TABLE will create implicit sequence
"member_member_id_seq" for "serial" column "member.member_id"

December 19, 2004 19:17:32.007
<<<<<    NoticeResponseMessage
Message: NOTICE:  CREATE TABLE / PRIMARY KEY will create implicit index
"member_pkey" for table "member"

December 19, 2004 19:17:32.047
<<<<<    ErrorResponseMessage
Error message: ERROR:  relation "member_member_id_seq" already exists

And here is a sequence ending with a duplicate key violation (again, the
drops worked fine.):

December 19, 2004 19:17:40.577
<<<<<    ReadyForQueryMessage

December 19, 2004 19:17:40.577
>>>>>    QueryMessage
'create table member (
    member_id serial primary key,
    member_number integer)'

December 19, 2004 19:17:40.578
<<<<<    NoticeResponseMessage
Message: NOTICE:  CREATE TABLE will create implicit sequence
"member_member_id_seq" for "serial" column "member.member_id"

December 19, 2004 19:17:40.578
<<<<<    NoticeResponseMessage
Message: NOTICE:  CREATE TABLE / PRIMARY KEY will create implicit index
"member_pkey" for table "member"

December 19, 2004 19:17:40.617
<<<<<    ErrorResponseMessage
Error message: ERROR:  duplicate key violates unique constraint
"pg_class_relname_nsp_index"


It's worrying that sometimes this works, and sometimes it does not.

Does anyone have any ideas what I'm getting wrong here?

Thanks,
    Bruce
--
Make the most of your skills - with OpenSkills
http://www.openskills.com

Bruce Badger <bbadger@openskills.com> writes:
> I'm building a system in Smalltalk and using unit tests (SUnit)
> extensively.  The unit tests cover all model and persistence aspects of
> the system, and part of what they do is create and drop the tables in
> the system for each bunch of tests.  So, tables are being rapidly
> created and dropped.

> Sometimes, the drops don't work, and I get errors when I try and create
> the tables again like:

What this looks like to me is a race condition between multiple
instances of the same test, ie, two or more connections trying to create
identically-named tables at about the same time.  The "duplicate key"
error is really not possible if the problem is that "the drop didn't
work" --- that message can only come out if some other process creates a
conflicting entry between the point where we check for pre-existence of
the table (leading to the "relation already exists" error) and the point
where we physically install index entries for the table's catalog
entries.

So, check your control logic to see if it's scheduling concurrent copies
of the same test.

            regards, tom lane

On Tue, 2004-12-21 at 02:22, Tom Lane wrote:
> Bruce Badger <bbadger@openskills.com> writes:
> > Sometimes, the drops don't work, and I get errors when I try and create
> > the tables again like:
>
> What this looks like to me is a race condition between multiple
> instances of the same test, ie, two or more connections trying to create
> identically-named tables at about the same time.

Yes, it looked to me like a race condition somewhere.

As it happens, I wrote the PostgreSQL drivers for Smalltalk, so I was
able to easily add code to only allow one connection at a time.  Any
attempt to have more than one active connection would cause a walk-back
(stack dump).

I ran the test code again, and experienced exactly the same symptoms as
before (i.e. table drop appearing to work, but then hitting problem as
if the table had not been dropped) and the multi-connection trap did
*not* fire (i.e. there was never more than one connection at a time).

As it happens, this is reflected in the log I mentioned.  The trap does
confirm that only one connection is active at a time, though.

The log is 40k uncompressed, so I didn't want to post it here.  I'd be
delighted to email it along to anyone who is interested though (he
suggested hopefully).

Many thanks for the response, Tom.

All the best,
    Bruce
--
Make the most of your skills - with OpenSkills
http://www.openskills.com