I've loaded up mailman's test suite and one step at a time reduced the
failing test to more granular steps, removing one at a time to
continue to reproduce the error. It turns out there is a fundamental
bug in the post_update feature that has existed for years and is only
becoming apparent now that the feature reports on missed rows.
issue is at
https://bitbucket.org/zzzeek/sqlalchemy/issues/4187/post_update-fails-if-the-parent-object-is.
hopefully fixed in a few hours and hopefully backports to 1.1.x
though it's only critical that it gets to 1.2 since that's where the
assertion was added.
On Sun, Jan 28, 2018 at 12:19 PM, Mike Bayer <mike...@zzzcomputing.com> wrote:
> On Sat, Jan 27, 2018 at 11:54 PM, <raj.abhila...@gmail.com> wrote:
>> Hi Mike,
>>
>> I am one of the other Mailman developers, just following up on behalf of
>> Mark.
>>
>> On Sunday, 21 January 2018 06:51:29 UTC-8, Mike Bayer wrote:
>>>
>>> here are a few questions:
>>>
>>> 1. is mailman using the version_id mapper feature with these mappings ?
>>
>>
>> No, Mailman isn't using version_id mapper feature.
>>
>>>
>>>
>>> 2. do mailman mappings use natural primary keys? in the above example
>>> are the primary keys of objects changing?
>>>
>> No, the primary keys of the objects aren't changing.
>>
>> I tried to run the test with echo='debug' to produce SQL statements emitted
>> and found something odd. I see that the UPDATE statement from
>> post_update=True is being emitted *after* the DELETE statement, when trying
>> to delete a record. This causes the UPDATE statement to error out due to
>> non-existent row. This happens both in 1.1 and 1.2, although 1.1 passes it
>> silently while 1.2 errors out with the stack trace that Mark presented
>> above.
>>
>> Here is the relevant SQL statements:
>>
>> User.id == 2 is being accessed after it has been deleted.
>>
>> 1.1.15:
>>
>>
>> 018-01-27 20:32:54,580 INFO sqlalchemy.engine.base.Engine DELETE FROM user
>> WHERE user.id = ?
>> 2018-01-27 20:32:54,580 INFO sqlalchemy.engine.base.Engine (2,)
>> 2018-01-27 20:32:54,581 INFO sqlalchemy.engine.base.Engine UPDATE user SET
>> _preferred_address_id=? WHERE user.id = ?
>> 2018-01-27 20:32:54,581 INFO sqlalchemy.engine.base.Engine (None, 2)
>> 2018-01-27 20:32:54,582 INFO sqlalchemy.engine.base.Engine DELETE FROM
>> preferences WHERE preferences.id = ?
>> 2018-01-27 20:32:54,582 INFO sqlalchemy.engine.base.Engine (4,)
>> 2018-01-27 20:32:54,583 INFO sqlalchemy.engine.base.Engine SELECT
>> user.password AS user_password, user.id AS user_id, user.display_name AS
>> user_display_name, user._user_id AS user__user_id, user._created_on AS
>> user__created_on, user.is_server_owner AS user_is_server_owner,
>> user._preferred_address_id AS user__preferred_address_id,
>> user.preferences_id AS user_preferences_id
>> FROM user ORDER BY user.id
>> 2018-01-27 20:32:54,584 INFO sqlalchemy.engine.base.Engine ()
>>
>> 1.2.2:
>>
>>
>> 2018-01-27 20:26:58,981 INFO sqlalchemy.engine.base.Engine DELETE FROM user
>> WHERE user.id = ?
>> 2018-01-27 20:26:58,982 INFO sqlalchemy.engine.base.Engine (2,)
>> 2018-01-27 20:26:58,982 INFO sqlalchemy.engine.base.Engine UPDATE user SET
>> _preferred_address_id=? WHERE user.id = ?
>> 2018-01-27 20:26:58,983 INFO sqlalchemy.engine.base.Engine (None, 2)
>> 2018-01-27 20:26:58,983 INFO sqlalchemy.engine.base.Engine ROLLBACK
>> sqlalchemy.orm.exc.StaleDataError: UPDATE statement on table 'user' expected
>> to update 1 row(s); 0 were matched.
>>
>>
>>
>> This[1] is the 'user' model definition and the foreign key that should be
>> dis-connected before the DELETE, as is my understanding at least.
>
> Well, i just recreated your User/ Address/ Preferences model and tried
> every combination of deleting / removing Address, Preference, and User
> objects / attributes using a loop with flags iterating through 1024
> different permutations, and I can't reproduce that condition, the post
> update always does the right thing. From what we see, we know that
> the User object is definitely subject to a session.delete(), but as
> far as other objects, it's not clear yet.
>
> So, need to know a lot more detail:
>
> 1. what is the *full* SQL output of every row being altered within this test
>
> 2. are you manipulating the integer foreign key attributes of objects?
> E.g. user.preferred_address_id = None? Are you manipulating
> relationship-bound attributes? e.g. user.preferred_address = None ?
> are the two approaches being combined?
>
> 3. can you place a session.flush() right before the Query in question
> so that the flush simply proceeds
>
> 4. right before this flush and/or Query proceeds, what are the
> contents of: session.deleted, session.dirty, session.new ?
>
> 5. are relationships being reassigned? like
> user1.addresses.append(user2.address[0]) ?
>
> Alternatively:
>
> Below is a sample of the relevant bits of the model in isolation, with
> a delete of a User and Preferences object. if you could make this
> test show the problem, that would be the most effective way to
> immediately show what's happening.
>
> from sqlalchemy import *
> from sqlalchemy.orm import *
> from sqlalchemy.ext.declarative import declarative_base
>
> Base = declarative_base()
>
>
> class User(Base):
> __tablename__ = 'user'
> id = Column(Integer, primary_key=True)
> favorite_address_id = Column(ForeignKey('address.id'))
> addresses = relationship("Address", backref="user",
> primaryjoin=lambda: User.id == Address.user_id)
> favorite_address = relationship(
> "Address", post_update=True,
> primaryjoin=lambda: User.favorite_address_id == Address.id)
>
> preferences_id = Column(Integer, ForeignKey('preferences.id'), index=True)
> preferences = relationship(
> 'Preferences', backref=backref('user', uselist=False))
>
>
> class Preferences(Base):
> __tablename__ = 'preferences'
> id = Column(Integer, primary_key=True)
>
>
> class Address(Base):
> __tablename__ = 'address'
> id = Column(Integer, primary_key=True)
> user_id = Column(ForeignKey('user.id'))
>
> e = create_engine("sqlite://", echo=True)
> s = Session(e)
>
>
> Base.metadata.create_all(e)
> p1 = Preferences()
> a1, a2, a3 = Address(), Address(), Address()
> u1 = User(addresses=[a1, a2, a3], favorite_address=a2, preferences=p1)
> s.add(u1)
> s.commit()
>
> s.delete(p1)
> s.delete(u1)
> s.commit()
>
>
>
>
>
>
>
>>
>> [1]:
>> https://gitlab.com/mailman/mailman/blob/master/src/mailman/model/user.py#L68
>>
>> Please let me know if you need any more information about this.
>>
>> thanks,
>> Abhilash
>>
>>
>>
>>>
>>>
>>>
>>> On Sun, Jan 21, 2018 at 8:24 AM, Mike Bayer <mik...@zzzcomputing.com>
>>> wrote:
>>> > On Sat, Jan 20, 2018 at 8:19 PM, Mark Sapiro <ma...@msapiro.net> wrote:
>>> >> Gnu Mailman 3 uses SQL Alchemy to access SQL databases. We have an
>>> >> issue
>>> >> with one of or unit tests which passes with SQLAlchemy <= 1.1.15 but
>>> >> which
>>> >> fails with SQLAlchemy >= 1.2. The failure is independent of the backend
>>> >> (sglite, mysql or pgsql). Here's a traceback from the failure.
>>> >>
>>> >> Traceback (most recent call last):
>>> >> File "/builds/mailman/mailman/src/mailman/model/tests/test_user.py",
>>> >> line
>>> >> 184, in test_absorb_memberships
>>> >> all_users = list(self._manager.users)
>>> >> File "/builds/mailman/mailman/src/mailman/model/usermanager.py", line
>>> >> 102,
>>> >> in users
>>> >> yield from store.query(User).order_by(User.id).all()
>>> >> File
>>> >>
>>> >> "/builds/mailman/mailman/.tox/py36-nocov/lib/python3.6/site-packages/sqlalchemy/orm/query.py",
>>> >> line 2726, in all
>>> >> return list(self)
>>> >> File
>>> >>
>>> >> "/builds/mailman/mailman/.tox/py36-nocov/lib/python3.6/site-packages/sqlalchemy/orm/query.py",
>>> >> line 2877, in __iter__
>>> >> self.session._autoflush()
>>> >> File
>>> >>
>>> >> "/builds/mailman/mailman/.tox/py36-nocov/lib/python3.6/site-packages/sqlalchemy/orm/session.py",
>>> >> line 1434, in _autoflush
>>> >> self.flush()
>>> >> File
>>> >>
>>> >> "/builds/mailman/mailman/.tox/py36-nocov/lib/python3.6/site-packages/sqlalchemy/orm/session.py",
>>> >> line 2243, in flush
>>> >> self._flush(objects)
>>> >> File
>>> >>
>>> >> "/builds/mailman/mailman/.tox/py36-nocov/lib/python3.6/site-packages/sqlalchemy/orm/session.py",
>>> >> line 2369, in _flush
>>> >> transaction.rollback(_capture_exception=True)
>>> >> File
>>> >>
>>> >> "/builds/mailman/mailman/.tox/py36-nocov/lib/python3.6/site-packages/sqlalchemy/util/langhelpers.py",
>>> >> line 66, in __exit__
>>> >> compat.reraise(exc_type, exc_value, exc_tb)
>>> >> File
>>> >>
>>> >> "/builds/mailman/mailman/.tox/py36-nocov/lib/python3.6/site-packages/sqlalchemy/util/compat.py",
>>> >> line 187, in reraise
>>> >> raise value
>>> >> File
>>> >>
>>> >> "/builds/mailman/mailman/.tox/py36-nocov/lib/python3.6/site-packages/sqlalchemy/orm/session.py",
>>> >> line 2333, in _flush
>>> >> flush_context.execute()
>>> >> File
>>> >>
>>> >> "/builds/mailman/mailman/.tox/py36-nocov/lib/python3.6/site-packages/sqlalchemy/orm/unitofwork.py",
>>> >> line 391, in execute
>>> >> rec.execute(self)
>>> >> File
>>> >>
>>> >> "/builds/mailman/mailman/.tox/py36-nocov/lib/python3.6/site-packages/sqlalchemy/orm/unitofwork.py",
>>> >> line 542, in execute
>>> >> persistence.post_update(self.mapper, states, uow, cols)
>>> >> File
>>> >>
>>> >> "/builds/mailman/mailman/.tox/py36-nocov/lib/python3.6/site-packages/sqlalchemy/orm/persistence.py",
>>> >> line 234, in post_update
>>> >> mapper, table, update)
>>> >> File
>>> >>
>>> >> "/builds/mailman/mailman/.tox/py36-nocov/lib/python3.6/site-packages/sqlalchemy/orm/persistence.py",
>>> >> line 982, in _emit_post_update_statements
>>> >> (table.description, len(records), rows))
>>> >> sqlalchemy.orm.exc.StaleDataError: UPDATE statement on table 'user'
>>> >> expected
>>> >> to update 1 row(s); 0 were matched.
>>> >
>>> >
>>> > so StaleDataError is thrown when the ORM seeks to update or delete a
>>> > row based on primary key, and the row which that statement would match
>>> > is no longer present. This is essentially an assertion that the state
>>> > of the database is what the ORM expects based on its internal state.
>>> > The "stale" name refers to the typical case that some other
>>> > transaction has changed the state of the database while our
>>> > transaction is proceeding, however it is often the case that some
>>> > combination of how the mappings are set up combined with what the
>>> > application is doing causes the ORM to not have a row available which
>>> > should.
>>> >
>>> > In this case, the operation is specifically in relationship to the
>>> > usage of the "post_update" feature of mappings
>>> >
>>> > (http://docs.sqlalchemy.org/en/latest/orm/relationship_persistence.html#post-update)
>>> > , since we can see that in the stack trace. The difference between
>>> > 1.1 and 1.2 is that the StaleDataError assertions have been added to
>>> > the post update system:
>>> >
>>> > http://docs.sqlalchemy.org/en/latest/changelog/migration_12.html#post-update-integrates-with-orm-versioning
>>> > which is almost definitely part of the reason you get an error in 1.2
>>> > and not in 1.1.
>>> >
>>> > What remains to be understood is whether your test produced an UPDATE
>>> > that didn't match a row in any case, and in 1.2, we just happen to be
>>> > raising an error for it, whereas under 1.1 this error condition
>>> > silently passed. Or, if the change in 1.2 itself has a regression and
>>> > the steps / SQL emitted are erroneously different.
>>> >
>>> > Things that would help us to see would be: 1. a look at the models
>>> > in question and how post_update is being set up and 2. when the
>>> > test runs, grab the full SQL output, using something like echo='debug'
>>> > on create_engine() or logging the "sqlalchemy.engine" logger. We
>>> > want to look at the exact sequence of SQL emitted both for the 1.1
>>> > series and the 1.2 series, to see what the nature of the UPDATE
>>> > against a missing row is. If it looks like things work exactly the
>>> > same in 1.1 then that means your post_update has been missing this row
>>> > the whole time.
>>> >
>>> > This is just the top level information, I haven't looked at your
>>> > actual code yet just the stack trace. I'm not available today but
>>> > later in the week if you can produce self-contained reproducing
>>> > examples then I can further examine if we have a regression on the
>>> > SQLAlchemy side, or if this is expected behavior.
>>> >
>>> >
>>> >
>>> >
>>> >
>>> >
>>> >>
>>> >>
>>> >> The test that fails sets up 3 mailing lists and subscribes 2 users
>>> >> (Anne and
>>> >> Bart) to some or all of the lists with different roles. Then user Anne
>>> >> "absorbs" user Bart so user Bart is deleted and user Anne assumes all
>>> >> Bart's
>>> >> memberships. The actual code in the test may not be intelligible
>>> >> without
>>> >> more Mailman knowledge, but it is:
>>> >> def test_absorb_memberships(self):
>>> >> # When a user is absorbed, all of their user-subscribed
>>> >> memberships
>>> >> # are relinked to the absorbing user.
>>> >> mlist2 = create_list('te...@example.com')
>>> >> mlist3 = create_list('te...@example.com')
>>> >> with transaction():
>>> >> # This has to happen in a transaction so that both the user
>>> >> and
>>> >> # the preferences objects get valid ids.
>>> >> bart = self._manager.create_user('b...@example.com', 'Bart
>>> >> Person')
>>> >> set_preferred(bart)
>>> >> # Subscribe both users to self._mlist.
>>> >> self._mlist.subscribe(self._anne, MemberRole.member)
>>> >> self._mlist.subscribe(bart, MemberRole.moderator)
>>> >> # Subscribe only Bart to mlist2.
>>> >> mlist2.subscribe(bart, MemberRole.owner)
>>> >> # Subscribe only Bart's address to mlist3.
>>> >> mlist3.subscribe(bart.preferred_address, MemberRole.moderator)
>>> >> # There are now 4 memberships, one with Anne two with Bart's
>>> >> user
>>> >> and
>>> >> # one with Bart's address.
>>> >> all_members = list(self._manager.members)
>>> >> self.assertEqual(len(all_members), 4, all_members)
>>> >> # Do the absorption.
>>> >> self._anne.absorb(bart)
>>> >> # The Bart user has been deleted, leaving only the Anne user in
>>> >> the
>>> >> # user manager.
>>> >> all_users = list(self._manager.users)
>>> >> self.assertEqual(len(all_users), 1)
>>> >> self.assertEqual(all_users[0], self._anne)
>>> >> # There are no leftover memberships for user Bart. Anne owns
>>> >> all
>>> >> the
>>> >> # memberships.
>>> >> all_members = list(self._manager.members)
>>> >> self.assertEqual(len(all_members), 4, all_members)
>>> >> self.assertEqual(self._anne.memberships.member_count, 4)
>>> >> memberships = {(member.list_id, member.role): member
>>> >> for member in self._anne.memberships.members}
>>> >> # Note that Anne is now both a member and moderator of the test
>>> >> list.
>>> >> self.assertEqual(set(memberships), set([
>>> >> ('test.example.com', MemberRole.member),
>>> >> ('test.example.com', MemberRole.moderator),
>>> >> ('test2.example.com', MemberRole.owner),
>>> >> ('test3.example.com', MemberRole.moderator),
>>> >> ]))
>>> >> # Both of Bart's previous user subscriptions are now
>>> >> transferred to
>>> >> # the Anne user.
>>> >> self.assertEqual(
>>> >> memberships[('test.example.com',
>>> >> MemberRole.moderator)].address,
>>> >> self._anne.preferred_address)
>>> >> self.assertEqual(
>>> >> memberships[('test2.example.com',
>>> >> MemberRole.owner)].address,
>>> >> self._anne.preferred_address)
>>> >> # Bart's address was subscribed; it must not have been changed.
>>> >> Of
>>> >> # course, Anne now controls ba...@example.com.
>>> >> key = ('test3.example.com', MemberRole.moderator)
>>> >> self.assertEqual(memberships[key].address.email,
>>> >> 'ba...@example.com')
>>> >> self.assertEqual(self._manager.get_user('ba...@example.com'),
>>> >> self._anne)
>>> >>
>>> >>
>>> >>
>>> >> The start of the traceback is the statement
>>> >> # The Bart user has been deleted, leaving only the Anne user in
>>> >> the
>>> >> # user manager.
>>> >> all_users = list(self._manager.users)
>>> >> Versions older than 1.2 do not throw the
>>> >> sqlalchemy.orm.exc.StaleDataError
>>> >> exception at this point.
>>> >>
>>> >> If I attempt to fix the test by doing the `self._anne.absorb(bart)` in
>>> >> a
>>> >> transaction that gets committed on completion, the same exception is
>>> >> thrown
>>> >> on the commit.
>>> >>
>>> >> Does anyone have any ideas about this?
>>> >>
>>> >> --
>>> >> SQLAlchemy -
>>> >> The Python SQL Toolkit and Object Relational Mapper
>>> >>
>>> >> http://www.sqlalchemy.org/
>>> >>
>>> >> To post example code, please provide an MCVE: Minimal, Complete, and
>>> >> Verifiable Example. See http://stackoverflow.com/help/mcve for a full
>>> >> description.
>>> >> ---
>>> >> You received this message because you are subscribed to the Google
>>> >> Groups
>>> >> "sqlalchemy" group.
>>> >> To unsubscribe from this group and stop receiving emails from it, send
>>> >> an
>>> >> email to sqlalchemy+...@googlegroups.com.
>>> >> To post to this group, send email to sqlal...@googlegroups.com.
>>> >> Visit this group at https://groups.google.com/group/sqlalchemy.
>>> >> For more options, visit https://groups.google.com/d/optout.
>>
>> --
>> SQLAlchemy -
>> The Python SQL Toolkit and Object Relational Mapper
>>
>> http://www.sqlalchemy.org/
>>
>> To post example code, please provide an MCVE: Minimal, Complete, and
>> Verifiable Example. See http://stackoverflow.com/help/mcve for a full
>> description.
>> ---
>> You received this message because you are subscribed to the Google Groups
>> "sqlalchemy" group.
>> To unsubscribe from this group and stop receiving emails from it, send an
>> email to sqlalchemy+unsubscr...@googlegroups.com.
>> To post to this group, send email to sqlalchemy@googlegroups.com.
>> Visit this group at https://groups.google.com/group/sqlalchemy.
>> For more options, visit https://groups.google.com/d/optout.
--
SQLAlchemy -
The Python SQL Toolkit and Object Relational Mapper
http://www.sqlalchemy.org/
To post example code, please provide an MCVE: Minimal, Complete, and Verifiable
Example. See http://stackoverflow.com/help/mcve for a full description.
---
You received this message because you are subscribed to the Google Groups
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to sqlalchemy+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.
