Expire on delete (was not expired before)

[sqlalchemy-bot]

Migrated issue, originally created by Dmytro Starosud (@dima-starosud)

Regression from 1.1.15 to 1.2.11. Maybe related to this.

Please consider following code snippet.

Base = declarative_base()

class Parent(Base):
    __tablename__ = 'parent'
    id = Column(Integer, primary_key=True)

    children = relationship(
        'Child',
        foreign_keys='Child.parent_id', back_populates='parent', cascade='all, delete-orphan')

    first_child_id = Column(Integer, ForeignKey('child.id'))
    first_child = relationship('Child', foreign_keys=first_child_id, post_update=True)

    updated_at = Column(DateTime(), onupdate=func.now())

class Child(Base):
    __tablename__ = 'child'
    id = Column(Integer, primary_key=True)
    parent_id = Column(Integer, ForeignKey(Parent.id), nullable=False)
    parent = relationship(Parent, foreign_keys=parent_id, back_populates='children')

Base.metadata.create_all(session.bind, checkfirst=True)

child = Child()
parent = Parent(children=[child], first_child=child)
session.add(parent)
session.flush()
parent_id = parent.id
session.expunge_all()

@event.listens_for(Parent, 'expire')
def receive_expire(target, attrs):
    traceback.print_stack()

parent = session.query(Parent).get(parent_id)
session.delete(parent)
session.flush()

print(parent.updated_at)

With SQLAlchemy==1.1.15 it outputs 2018-08-23 12:06:19.291603, nothing more and no failures.

With SQLAlchemy==1.2.11 it outputs two stack traces: one from expire event and one when trying access parent.updated_at.

  File "coze.py", line 62, in <module>
    session.flush()
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/session.py", line 2254, in flush
    self._flush(objects)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/session.py", line 2344, in _flush
    flush_context.execute()
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/unitofwork.py", line 391, in execute
    rec.execute(self)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/unitofwork.py", line 542, in execute
    persistence.post_update(self.mapper, states, uow, cols)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/persistence.py", line 234, in post_update
    mapper, table, update)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/persistence.py", line 975, in _emit_post_update_statements
    c, c.context.compiled_parameters[0])
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/persistence.py", line 1163, in _postfetch_post_update
    for c in postfetch_cols if c in
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/state.py", line 593, in _expire_attributes
    self.manager.dispatch.expire(self, attribute_names)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/event/attr.py", line 284, in __call__
    fn(*args, **kw)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/events.py", line 202, in wrap
    return fn(state.obj(), *arg, **kw)
  File "coze.py", line 57, in receive_expire
    traceback.print_stack()
Traceback (most recent call last):
  File "coze.py", line 64, in <module>
    print(parent.updated_at)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/attributes.py", line 242, in __get__
    return self.impl.get(instance_state(instance), dict_)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/attributes.py", line 594, in get
    value = state._load_expired(state, passive)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/state.py", line 608, in _load_expired
    self.manager.deferred_scalar_loader(self, toload)
  File "/usr/local/lib/python3.5/site-packages/sqlalchemy/orm/loading.py", line 881, in load_scalar_attributes
    raise orm_exc.ObjectDeletedError(state)
sqlalchemy.orm.exc.ObjectDeletedError: Instance '<Parent at 0x7fa8177dc160>' has been deleted, or its row is otherwise not present.

Please clarify. Does this mean deleted instance cannot be used after flush any more?

Thanks a lot in advance.

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

that likely is the change which affected this, so, why do you want to look at the now nonexistent "updated_at" when you've just emitted a DELETE for that row?

[sqlalchemy-bot]

Dmytro Starosud (@dima-starosud) wrote:

@zzzeek After every flush our system collects information about all the objects participating in that flush to be reported.

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

well, the change mentioned is intended to expire it for the purpose of updates, shouldn't matter for deletes, but often within the scope of post_update there are some linked effects that can't easily be unlinked, will have to look.

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

so we'd look at this as the patch:

    if not uowtransaction.is_deleted(state) and postfetch_cols:
        state._expire_attributes(state.dict,
                                 [mapper._columntoproperty[c].key
                                  for c in postfetch_cols if c in
                                  mapper._columntoproperty]
                                 )

however, if I even remove that whole block of code, none of the tests fail, so that is another regression in that when I made https://bitbucket.org/zzzeek/sqlalchemy/commits/9dee44ae2f8b#chg-test/orm/test_cycles.py I did not test this code so that means I have to be way more careful here and add tests for that too.

[sqlalchemy-bot]

Dmytro Starosud (@dima-starosud) wrote:

@zzzeek thank you for a quick answer.

Sorry I am not curtain I clearly understood what you said. Are you going to prepare patch of 1.2 release, so we can upgrade to it?

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

it means I added code that was not tested which means I have to consider that also.

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

note that if I fix this you will still probably have issues, as the updated_at is still expired from any other UPDATES, so this modification to your test will still fail:

session = Session(e)

child1 = Child()
child2 = Child()
parent = Parent(children=[child1, child2], first_child=child1)
session.add(parent)
session.flush()
parent_id = parent.id
session.expunge_all()

parent = session.query(Parent).get(parent_id)
child2 = session.query(Child).order_by(Child.id)[1]
parent.first_child = child2
session.flush()

session.delete(parent)
session.flush()

print(parent.updated_at)

overall, you really can't depend on database-generated values to be present after an object is removed from the session.

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

as part of this fix I have identified another inconsistency which is that client-side updated_at defaults are also refreshed when the object is deleted as a result of the UPDATE that took place. I think that is also wrong. In this case, even though we are emitting an UPDATE and applying both client-side and server-side onupdates to that UPDATE, we ultimately DELETE the row. Previously, these interim values were discarded from memory as well regardless of how they got there. So I'm going to make it skip the entire post_update_onupdate added in #3472 if the object is set for DELETE.

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

https://gerrit.sqlalchemy.org/#/q/Ieac845348979df296bcf7e785c0353bdc6074220

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

Don't run postfetch_post_update for a DELETE

Fixed 1.2 regression caused by :ticket:3472 where the handling of an "updated_at" style column within the context of a post-update operation would also occur for a row that is to be deleted following the update, meaning both that a column with a Python-side value generator would show the now-deleted value that was emitted for the UPDATE before the DELETE (which was not the previous behavor), as well as that a SQL- emitted value generator would have the attribute expired, meaning the previous value would be unreachable due to the row having been deleted and the object detached from the session.The "postfetch" logic that was added as part of :ticket:3472 is now skipped entirely for an object that ultimately is to be deleted.

Fixes: #4327 Change-Id: Ieac845348979df296bcf7e785c0353bdc6074220

→ 1b5393db36a6

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

Don't run postfetch_post_update for a DELETE

Fixed 1.2 regression caused by :ticket:3472 where the handling of an "updated_at" style column within the context of a post-update operation would also occur for a row that is to be deleted following the update, meaning both that a column with a Python-side value generator would show the now-deleted value that was emitted for the UPDATE before the DELETE (which was not the previous behavor), as well as that a SQL- emitted value generator would have the attribute expired, meaning the previous value would be unreachable due to the row having been deleted and the object detached from the session.The "postfetch" logic that was added as part of :ticket:3472 is now skipped entirely for an object that ultimately is to be deleted.

Fixes: #4327 Change-Id: Ieac845348979df296bcf7e785c0353bdc6074220 (cherry picked from commit 1b5393db36a6c4353d41c7065b29a377d7c3b9b2)

→ 066c25ba8927

[sqlalchemy-bot]

Dmytro Starosud (@dima-starosud) wrote:

Thanks @zzzeek for quick fix! Should I expect this in 1.2.12? When do you think that version be released?

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

I'll likely release this week

[sqlalchemy-bot]

Dmytro Starosud (@dima-starosud) wrote:

Cool! Thank you a lot!

[sqlalchemy-bot]

Dmytro Starosud (@dima-starosud) wrote:

Hello @zzzeek !

Should I wait for more for 1.2.12 or it's better to find a workaround?

Thanks a lot in advance.

[sqlalchemy-bot]

Michael Bayer (@zzzeek) wrote:

there should be a 1.2.12 in the coming days I can perhaps try this week

[sqlalchemy-bot]

Changes by Michael Bayer (@zzzeek):

• added labels: orm

[sqlalchemy-bot]

Changes by Michael Bayer (@zzzeek):

• set milestone to "1.2.x"

[sqlalchemy-bot]

Changes by Michael Bayer (@zzzeek):

• changed status to closed