psycopg2.errors.DuplicateObject: type "temp_store" already exists

[jensens]

I have no idea how to start debuggng this one, what can cause it? Looks like its Postgres related, so I start here. It appears while creating a new folder in Plone (like this traceback) but also if I want to create a new user.

Traceback (innermost last):
  Module ZPublisher.WSGIPublisher, line 162, in transaction_pubevents
  Module ZPublisher.WSGIPublisher, line 371, in publish_module
  Module ZPublisher.WSGIPublisher, line 266, in publish
  Module ZPublisher.mapply, line 85, in mapply
  Module ZPublisher.WSGIPublisher, line 63, in call_object
  Module plone.z3cform.layout, line 63, in __call__
  Module plone.z3cform.layout, line 47, in update
  Module plone.dexterity.browser.add, line 138, in update
  Module plone.z3cform.fieldsets.extensible, line 65, in update
  Module plone.z3cform.patch, line 30, in GroupForm_update
  Module z3c.form.group, line 145, in update
  Module plone.app.z3cform.csrf, line 22, in execute
  Module z3c.form.action, line 98, in execute
  Module z3c.form.button, line 315, in __call__
  Module z3c.form.button, line 170, in __call__
  Module plone.dexterity.browser.add, line 116, in handleAdd
  Module z3c.form.form, line 265, in createAndAdd
  Module plone.dexterity.browser.add, line 91, in add
  Module plone.dexterity.utils, line 178, in addContentToContainer
  Module Products.BTreeFolder2.BTreeFolder2, line 465, in _setObject
  Module zope.event, line 32, in notify
  Module zope.component.event, line 27, in dispatch
  Module zope.component._api, line 134, in subscribers
  Module zope.interface.registry, line 448, in subscribers
  Module zope.interface.adapter, line 899, in subscribers
  Module zope.component.event, line 36, in objectEventNotify
  Module zope.component._api, line 134, in subscribers
  Module zope.interface.registry, line 448, in subscribers
  Module zope.interface.adapter, line 899, in subscribers
  Module five.intid.intid, line 145, in moveIntIdSubscriber
  Module zope.component.hooks, line 135, in adapter_hook
  Module zope.security.adapter, line 84, in __call__
  Module five.intid.keyreference, line 95, in __init__
  Module ZODB.Connection, line 216, in add
  Module ZODB.Connection, line 203, in new_oid
  Module relstorage.storage, line 562, in new_oid
  Module relstorage.storage.oid, line 113, in new_oid
  Module relstorage.storage.oid, line 122, in __preallocate_oids
  Module contextlib, line 113, in __enter__
  Module relstorage.adapters.connections, line 406, in borrowing
  Module relstorage.adapters.connections, line 436, in borrow
  Module relstorage.adapters.connections, line 313, in begin
  Module relstorage.adapters.connections, line 151, in open_if_needed
  Module relstorage.adapters.connections, line 158, in _open_connection
  Module relstorage.adapters.connmanager, line 387, in open_for_store
  Module relstorage.adapters.connmanager, line 310, in _call_hooks
  Module perfmetrics._metric, line 72, in perfmetrics._metric._AbstractMetricImpl.__call__
  Module relstorage.adapters.postgresql.mover, line 96, in on_store_opened
psycopg2.errors.DuplicateObject: type "temp_store" already exists
HINT:  A relation has an associated type of the same name, so you must use a name that doesn't conflict with any existing type.

[jensens]

Plone 5.2.6 RelStorage = 3.4.5 psycopg2 = 2.9.3 with Docker image postgres:12

[jamadden]

The first step would be to find out what temp_store is, if it exists. It shouldn't exist outside the scope of a single postgresql connection used as a RelStorage store connection (it's a temporary table, deleted when the connection closes), so if you open a new database connection (eg using psql) and can find the relation (not necessarily a table) temp_store in the catalogs, that's Bad. The solution would probably be to remove that object.

If there is no object of that name in an unrelated connection, then the connection involved in the stack trace is being misused somehow. It's possible an earlier error occurred that wasn't handled correctly and the connection is being re-used in an invalid state (when it should have been closed, it was instead returned to a pool). We'd need to find that error.

[jensens]

I am connected with psql and tried this:

temp_store does not appear in SELECT typname FROM pg_catalog.pg_type; nor in SELECT * FROM pg_catalog.pg_tables;.

SELECT n.nspname AS schemaname, c.relname, c.relkind FROM pg_class c JOIN pg_namespace n ON n.oid = c.relnamespace WHERE relname = 'temp_store'; shows an empty result.

Next step: breakpoint before https://github.com/zodb/relstorage/blob/f3825ba8071d19719447f52062930ae2e7199d6a/src/relstorage/adapters/postgresql/mover.py#L95

[jensens]

Debugger:

(Pdb) l
 90                         FOR EACH ROW
 91                         EXECUTE PROCEDURE temp_blob_chunk_delete_trigger();
 92                     """,
 93                 ]
 94                 breakpoint()
 95  ->             for stmt in ddl_stmts:
 96                     cursor.execute(stmt)
 97                 cursor.connection.commit()
 98     
 99             AbstractObjectMover.on_store_opened(self, cursor, restart)
100     
(Pdb) for stmt in ddl_stmts: print(stmt)

            CREATE TEMPORARY TABLE IF NOT EXISTS temp_store (
                zoid        BIGINT NOT NULL PRIMARY KEY,
                prev_tid    BIGINT NOT NULL,
                md5         CHAR(32),
                state       BYTEA
            ) ON COMMIT DELETE ROWS;

            CREATE TEMPORARY TABLE IF NOT EXISTS temp_store_replacements (
                zoid        BIGINT NOT NULL PRIMARY KEY,
                prev_tid    BIGINT NOT NULL,
                md5         CHAR(32),
                state       BYTEA
            ) ON COMMIT DELETE ROWS;

                CREATE TEMPORARY TABLE IF NOT EXISTS temp_blob_chunk (
                    zoid        BIGINT NOT NULL,
                    chunk_num   BIGINT NOT NULL,
                    chunk       OID,
                    PRIMARY KEY (zoid, chunk_num)
                ) ON COMMIT DELETE ROWS;

                -- This trigger removes blobs that get replaced before being
                -- moved to blob_chunk.  Note that it is never called when
                -- the temp_blob_chunk table is being dropped or truncated.
                CREATE TRIGGER temp_blob_chunk_delete
                    BEFORE DELETE ON temp_blob_chunk
                    FOR EACH ROW
                    EXECUTE PROCEDURE temp_blob_chunk_delete_trigger();

And there seems to be no such table:

(Pdb) cursor.execute("DROP TABLE temp_store;")
*** psycopg2.errors.UndefinedTable: table "temp_store" does not exist

[jensens]

Workaround: A dump of the whole database and restore in an empty database "fixes" the problem.

pg_dump -h localhost -p 5432 -U plone -W plone > /var/lib/postgresql/data/dump.sql

Then keep dump.sql, empty the whole storage folder, start with fresh dbinit from container, copy back dump.sql and then

psql -h localhost -p 5432 -U plone -W plone < /var/lib/postgresql/data/dump.sql

Anyway, I am curious what's the real problem. At least I will keep a copy of the defect database for now and move on.

[jamadden]

I missed in the original report where it said specifically that a type with the same name existed. That's very interesting, and I haven't seen that before.

(I'd also forgotten that we have the IF NOT EXISTS clause in there, which would prevent table-to-table conflicts.) Thanks for pulling this all up.

[jamadden]

I was never able to reproduce anything like this, so it seems like it was something "broken" in that environment's database, which makes it next to impossible to try to handle generically; closing.