Newly created Oracle Indexes are trying to be added as new.

[davebyrnew]

How do I debug Alembic to find out why it is trying to add existing newly-created indexes?

I have a table defined as such:

class EditEOB(BASE):
    '''This is the Edit EOB cross reference table.'''
    __tablename__ = 'edit_eob'
    __table_args__ = (Index('eob_edit_idx', 'eob_rid', 'edit_rid', 'relationship_type', 'effective_date', unique=True),
                      Index('pk_edit_eob', 'edit_rid', 'eob_rid', 'relationship_type', 'effective_date', unique=True))
    edit_rid = Column(Numeric(15, 0), ForeignKey('edit_base.edit_rid'), primary_key=True)
    eob_rid = Column(Numeric(15, 0), ForeignKey('eob_base.eob_rid'), primary_key=True)
    effective_date = Column(Date, primary_key=True)
    expiration_date = Column(Date)
    relationship_type = Column(String(3), primary_key=True)
    entry_date = Column(DateTime)
    entry_user_id = Column(String(15))
    dlm = Column(DateTime)
    ulm = Column(String(15))

The two indexes are already existing. From the debug:

DEBUG [sqlalchemy.engine.base.Engine] Row (u'EOB_EDIT_IDX', u'EOB_RID', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'EOB_EDIT_IDX', u'EDIT_RID', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'EOB_EDIT_IDX', u'RELATIONSHIP_TYPE', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'EOB_EDIT_IDX', u'EFFECTIVE_DATE', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'EOB_EDIT_IDX', u'EOB_RID', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'EOB_EDIT_IDX', u'EDIT_RID', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'EOB_EDIT_IDX', u'RELATIONSHIP_TYPE', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'EOB_EDIT_IDX', u'EFFECTIVE_DATE', u'NORMAL', u'UNIQUE', u'DISABLED', None)
INFO  [alembic.autogenerate.compare] Detected added index 'eob_edit_idx' on '['eob_rid', 'edit_rid', 'relationship_type', 'effective_date']'

I don't know if this is showing that the index exists or not. Using pysql and describing the table and index shows:

Name              Type         Null? Comments Indexes                         
----------------- ------------ ----- -------- ------------------------------- 
EDIT_RID          NUMBER(22)   N              EOB_EDIT_IDX(2), PK_EDIT_EOB(1) 
EOB_RID           NUMBER(22)   N              EOB_EDIT_IDX(1), PK_EDIT_EOB(2) 
EFFECTIVE_DATE    DATE(7)      N              PK_EDIT_EOB(4), EOB_EDIT_IDX(4) 
EXPIRATION_DATE   DATE(7)      Y                                              
RELATIONSHIP_TYPE VARCHAR2(3)  N              EOB_EDIT_IDX(3), PK_EDIT_EOB(3) 
ENTRY_DATE        DATE(7)      Y                                              
ENTRY_USER_ID     VARCHAR2(15) Y                                              
DLM               DATE(7)      Y                                              
ULM               VARCHAR2(15) Y                                              
base@BWCUAT desc eob_edit_idx
Property                Value                                                            
----------------------- ---------------------------------------------------------------- 
TABLE_OWNER             BASE                                                             
TABLE_NAME              EDIT_EOB                                                         
INDEX_TYPE              NORMAL                                                           
UNIQUENESS              UNIQUE                                                           
COMPRESSION             DISABLED                                                         
LEAF_BLOCKS                                                                            4 
DISTINCT_KEYS                                                                        803 
AVG_LEAF_BLOCKS_PER_KEY                                                                1 
Indexed Columns         EOB_RID(1), EDIT_RID(2), RELATIONSHIP_TYPE(3), EFFECTIVE_DATE(4) 

[davebyrnew]

Looking at the debug info:

INFO  [sqlalchemy.engine.base.Engine] SELECT a.index_name, a.column_name,
b.index_type, b.uniqueness, b.compression, b.prefix_length
FROM ALL_IND_COLUMNS a,
ALL_INDEXES b
WHERE
a.index_name = b.index_name
AND a.table_owner = b.table_owner
AND a.table_name = b.table_name
AND a.table_name = :table_name AND a.table_owner = :schema ORDER BY a.index_name, a.column_position
INFO  [sqlalchemy.engine.base.Engine] {'table_name': u'EDIT_EOB', 'schema': u'BASE'}
DEBUG [sqlalchemy.engine.base.Engine] Col ('INDEX_NAME', 'COLUMN_NAME', 'INDEX_TYPE', 'UNIQUENESS', 'COMPRESSION', 'PREFIX_LENGTH')
DEBUG [sqlalchemy.engine.base.Engine] Row (u'EOB_EDIT_IDX', u'EOB_RID', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'EOB_EDIT_IDX', u'EDIT_RID', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'EOB_EDIT_IDX', u'RELATIONSHIP_TYPE', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'EOB_EDIT_IDX', u'EFFECTIVE_DATE', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'PK_EDIT_EOB', u'EDIT_RID', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'PK_EDIT_EOB', u'EOB_RID', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'PK_EDIT_EOB', u'RELATIONSHIP_TYPE', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'PK_EDIT_EOB', u'EFFECTIVE_DATE', u'NORMAL', u'UNIQUE', u'DISABLED', None)
INFO  [sqlalchemy.engine.base.Engine] SELECT a.index_name, a.column_name,
b.index_type, b.uniqueness, b.compression, b.prefix_length
FROM ALL_IND_COLUMNS a,
ALL_INDEXES b
WHERE
a.index_name = b.index_name
AND a.table_owner = b.table_owner
AND a.table_name = b.table_name
AND a.table_name = :table_name AND a.table_owner = :schema ORDER BY a.index_name, a.column_position
INFO  [sqlalchemy.engine.base.Engine] {'table_name': u'EDIT_EOB', 'schema': u'BASE'}
DEBUG [sqlalchemy.engine.base.Engine] Col ('INDEX_NAME', 'COLUMN_NAME', 'INDEX_TYPE', 'UNIQUENESS', 'COMPRESSION', 'PREFIX_LENGTH')
INFO  [sqlalchemy.engine.base.Engine] SELECT
ac.constraint_name,
ac.constraint_type,
...

It looks like it is running the extract for indexes two times in a row. The first pulls back the correct information, but the second one doesn't pull back anything. Am I looking at this correctly?

[zzzeek]

the SQL queries you see are SQLAlchemy emitting reflection queries for the indexes. SQLAlchemy's index / table reflection capabilities are pretty solid, though not performance optimized, so it's unlikely they are doing the wrong thing based on their input.

but you're right, that second query against the same data that returns no rows looks odd. It looks like it's running on a different connection. what does your env.py look like? are you running against multiple database URLs ?

[davebyrnew]

My line in alembic.ini looks like: sqlalchemy.url = oracle+cx_oracle://####:####@###### where the # are replaced with the user id, password, and database name.

The three indexes that are being handled like this were all recently added. I have numerous indexes where this is not occurring.

[davebyrnew]

I see this same setup on indexes where it is not trying to re-add them:

SELECT a.index_name, a.column_name,
b.index_type, b.uniqueness, b.compression, b.prefix_length
FROM ALL_IND_COLUMNS a,
ALL_INDEXES b
WHERE
a.index_name = b.index_name
AND a.table_owner = b.table_owner
AND a.table_name = b.table_name
AND a.table_name = :table_name AND a.table_owner = :schema ORDER BY a.index_name, a.column_position
INFO  [sqlalchemy.engine.base.Engine] {'table_name': u'PRO', 'schema': u'BASE'}
DEBUG [sqlalchemy.engine.base.Engine] Col ('INDEX_NAME', 'COLUMN_NAME', 'INDEX_TYPE', 'UNIQUENESS', 'COMPRESSION', 'PREFIX_LENGTH')
DEBUG [sqlalchemy.engine.base.Engine] Row (u'PK_PRO_NAME_IDX', u'PRO_NAME', u'NORMAL', u'NONUNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'PK_PRO_PRO_ID', u'PRO_ID', u'NORMAL', u'UNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'PK_PRO_TYPE_IDX', u'PRO_TYPE', u'NORMAL', u'NONUNIQUE', u'DISABLED', None)
DEBUG [sqlalchemy.engine.base.Engine] Row (u'PRO_PRO_NUM_IDX', u'PRO_NUM', u'NORMAL', u'UNIQUE', u'DISABLED', None)
INFO  [sqlalchemy.engine.base.Engine] SELECT a.index_name, a.column_name,
b.index_type, b.uniqueness, b.compression, b.prefix_length
FROM ALL_IND_COLUMNS a,
ALL_INDEXES b
WHERE
a.index_name = b.index_name
AND a.table_owner = b.table_owner
AND a.table_name = b.table_name
AND a.table_name = :table_name AND a.table_owner = :schema ORDER BY a.index_name, a.column_position
INFO  [sqlalchemy.engine.base.Engine] {'table_name': u'PRO', 'schema': u'BASE'}
DEBUG [sqlalchemy.engine.base.Engine] Col ('INDEX_NAME', 'COLUMN_NAME', 'INDEX_TYPE', 'UNIQUENESS', 'COMPRESSION', 'PREFIX_LENGTH')

so it probably is not related to the issue.

[zzzeek]

OK, perhaps it's a logging anomaly, so usually, the issue of indexes being re-added has to do with the logic to compare them.

I've stared for five minutes and I dont see anything wrong so let me try that table.

[davebyrnew]

Is there a way to show the table and comparison logic using logging levels? Or does it require either using a python debugger (or updating the code to include logging statements)?

[zzzeek]

It mostly requires the python debugger which I just ran.

the bug is in SQLAlchemy but I don't know how to fix it. the Oracle dialect does not want to return the implicit index created for a primary key in the get_indexes() collection. because these indexes both mirror the columns in the primary key, they are individually assumed to be the primary key index.

which leads me to wonder why I get one difference in output than you do, I get a third index in the results that is in fact the primary key index. why does your table not have this?

2020-06-25 10:22:28,387 DEBUG sqlalchemy.engine.base.Engine Row ('EOB_EDIT_IDX', 'EOB_RID', 'NORMAL', 'UNIQUE', 'DISABLED', None)
2020-06-25 10:22:28,388 DEBUG sqlalchemy.engine.base.Engine Row ('EOB_EDIT_IDX', 'EDIT_RID', 'NORMAL', 'UNIQUE', 'DISABLED', None)
2020-06-25 10:22:28,388 DEBUG sqlalchemy.engine.base.Engine Row ('EOB_EDIT_IDX', 'RELATIONSHIP_TYPE', 'NORMAL', 'UNIQUE', 'DISABLED', None)
2020-06-25 10:22:28,388 DEBUG sqlalchemy.engine.base.Engine Row ('EOB_EDIT_IDX', 'EFFECTIVE_DATE', 'NORMAL', 'UNIQUE', 'DISABLED', None)
2020-06-25 10:22:28,388 DEBUG sqlalchemy.engine.base.Engine Row ('PK_EDIT_EOB', 'EDIT_RID', 'NORMAL', 'UNIQUE', 'DISABLED', None)
2020-06-25 10:22:28,388 DEBUG sqlalchemy.engine.base.Engine Row ('PK_EDIT_EOB', 'EOB_RID', 'NORMAL', 'UNIQUE', 'DISABLED', None)
2020-06-25 10:22:28,388 DEBUG sqlalchemy.engine.base.Engine Row ('PK_EDIT_EOB', 'RELATIONSHIP_TYPE', 'NORMAL', 'UNIQUE', 'DISABLED', None)
2020-06-25 10:22:28,389 DEBUG sqlalchemy.engine.base.Engine Row ('PK_EDIT_EOB', 'EFFECTIVE_DATE', 'NORMAL', 'UNIQUE', 'DISABLED', None)
2020-06-25 10:22:28,389 DEBUG sqlalchemy.engine.base.Engine Row ('SYS_C007016366', 'EDIT_RID', 'NORMAL', 'UNIQUE', 'DISABLED', None)
2020-06-25 10:22:28,389 DEBUG sqlalchemy.engine.base.Engine Row ('SYS_C007016366', 'EOB_RID', 'NORMAL', 'UNIQUE', 'DISABLED', None)
2020-06-25 10:22:28,389 DEBUG sqlalchemy.engine.base.Engine Row ('SYS_C007016366', 'EFFECTIVE_DATE', 'NORMAL', 'UNIQUE', 'DISABLED', None)
2020-06-25 10:22:28,389 DEBUG sqlalchemy.engine.base.Engine Row ('SYS_C007016366', 'RELATIONSHIP_TYPE', 'NORMAL', 'UNIQUE', 'DISABLED', None)

[davebyrnew]

One of the two indexes is the primary key index. I add the primary key constraint after adding the unique index so that Oracle will use that instead of creating its own.

[zzzeek]

OK, we might have something here. ive done a careful diff here and there is in fact a column called "GENERATED" that differs between a PK implicit index and the ones generated. basically you will need the next SQLAlchemy 1.3 release to get this assuming I can do it. if you want to work around this right now you would need an include_object hook to skip these.

[davebyrnew]

I can wait for the next release. I'm using the include_object hook to exclude an Oracle view that I have mapped as a table. I'm not in immediate need of this, because I haven't switched to alembic to handle my migrations yet. I'm currently using it to validate the multiple environments (Development, QA, User Acceptance, and Production) and make sure they match layouts. For the time-being, I can just ignore those adds, but would like to be able to have the fix this year some time.

[zzzeek]

this is fun, why does one table not do this and the other one does. "ORA-01408: such column list already indexed"

[zzzeek]

your two indexes both have the columns in a different order than what the primary key would create. so oracle indexing is so bad you need two indexes like that with different ordering?

[zzzeek]

I can wait for the next release. I'm using the include_object hook to exclude an Oracle view that I have mapped as a table. I'm not in immediate need of this, because I haven't switched to alembic to handle my migrations yet. I'm currently using it to validate the multiple environments (Development, QA, User Acceptance, and Production) and make sure they match layouts. For the time-being, I can just ignore those adds, but would like to be able to have the fix this year some time.

oh well this is a small bug and i was going to release today as we are overdue in any case.

[zzzeek]

you can track this being resolved over at https://github.com/sqlalchemy/sqlalchemy/issues/5421 no issue in alembic