"Collection was loaded during event handling."

[io7m]

Hello! I've been tasked with migrating a moderately sized codebase (https://github.com/ThePalaceProject/circulation) from SQLAlchemy 1.3.25 to 1.4.30. I'm not very familiar with SQLAlchemy although I have spent the last week going through the tutorial and documentation and fixing other test issues. The circulation project has good test coverage, and I'm down to fixing a few remaining test failures to complete the upgrade.

I've, unfortunately, run into this exception: https://github.com/sqlalchemy/sqlalchemy/blob/main/lib/sqlalchemy/orm/attributes.py#L1416

I don't really understand what the exception is trying to tell me, or what the code that's triggering it is doing wrong. Is there anything in particular that I should be looking out for? Methods I should be searching for in the codebase to investigate?

I've managed to find this one issue talking about it:

2ab0687

... but I don't really understand what this means.

[zzzeek]

this means you have either an append event listener or a @validates listener on a collection, and the code within that handler is causing the collection to be loaded, when it is not expected to be loaded.

the main purpose of append /validates events are to work upon the value that is being appended, not the collection itself. so best strategy is, inside that event handler, don't touch the collection itself, if possible.

otherwise, the assertion here likely means the event is being triggered by a backref. the example below shows how to reproduce this issue and also how to work around it by only accessing the collection if this is the primary event and not the backref event.

from sqlalchemy import Column
from sqlalchemy import create_engine
from sqlalchemy import event
from sqlalchemy import ForeignKey
from sqlalchemy import Integer
from sqlalchemy import String
from sqlalchemy.ext.declarative import declarative_base
from sqlalchemy.orm import declarative_base
from sqlalchemy.orm import relationship
from sqlalchemy.orm import Session
Base = declarative_base()


class A(Base):
    __tablename__ = 'a'

    id = Column(Integer, primary_key=True)
    data = Column(String)
    bs = relationship("B", backref="a")


class B(Base):
    __tablename__ = 'b'
    id = Column(Integer, primary_key=True)
    a_id = Column(ForeignKey("a.id"))
    data = Column(String)

# this listen could also be a mapper @validates function, same thing
@event.listens_for(A.bs, "append")
def _append_a_b(target, value, initiator):
    target.bs
    return value

# one way to work around issue: check that the initiator is actually
# "bs" and not a backref
# @event.listens_for(A.bs, "append")
# def _append_a_b(target, value, initiator):
#     if initiator.key == 'bs':
#         target.bs
#     return value


e = create_engine("sqlite://", echo=True)
Base.metadata.create_all(e)

s = Session(e)

s.add(A(bs=[B()]))
s.commit()


a1 = s.query(A).first()
# here, a1 is expired.  the "bs" attribute is not loaded in
# a1.__dict__


b1 = B()

# now assign B().a = a1.  this fires a backref that also appends b1
# to a1.bs.  however, a1.bs does not load here, it places b1 in a "pending"
# collection that will be fulfilled if and when a1.bs is actually loaded.
b1.a = a1

# but the event handler does "target.bs" and populates a1.__dict__. we dont
# want that to happen hence the assertion

[io7m]

Thank you! I'll trying searching for both of those. Assuming I manage to fix it, I'll link to the diff here.

[io7m]

I've managed to work out what the problem is, but we can't actually fix this in circulation yet without a bit of extra work. I think this question is answered, though!

ThePalaceProject/circulation#163

I'd like to suggest adding a bit more debugging information to that assertion in the code. I ended up having to edit attributes.py locally and add various print statements in order to see exactly what was causing the assertion to fail in that case. It would have been really helpful if the assertion message said something like "Collection %s is not in the dictionary, so something unexpectedly caused it to be loaded. Here are the collections that are loaded: %s, the initiator was: %s". All of that information is available from the various dictionaries that are passed into the method, but the assertion message is generic. Obviously you'd come up with better wording and formatting! 😆

[zzzeek]

I'd like to suggest adding a bit more debugging information to that assertion in the code. I ended up having to edit attributes.py locally and add various print statements in order to see exactly what was causing the assertion to fail in that case.

I would recommend using pdb for this case, way easier than using print statements.

It would have been really helpful if the assertion message said something like "Collection %s is not in the dictionary, so something unexpectedly caused it to be loaded.

at the moment this was a mostly internal assertion, nobody has ever hit it before, so we can make more of an error message that indicates the parent mapper, that is the class that is mapped, and the attribute name.

Here are the collections that are loaded: %s,

that to me seems like arbitrary information unrelated to the error being raised.

the initiator was: %s".

that's not really possible here because the event has already passed. it's out of scope and also very bad for performance for SQLAlchemy to be walking up stack traces and/or persisting a bunch of "post-mortem" information about an event handler that's then thrown away in all cases except when this very rare error circumstance occurs. The dispatch collection for the attribute ultimately has references to the event-listener functions but it might be very involved to unwrap those into something identifiable given current architecture of the event system.

[io7m]

I would recommend using pdb for this case, way easier than using print statements.

Unfortunately, in this case, pdb appeared to change the behaviour of the code. I don't know if the underlying code is time sensitive, or if there's some kind of nondeterminism here, but I could consistently set a breakpoint on the assertion and, depending on how long I took looking at the data, continue execution and see the assertion succeed instead of failing. The only reliable way I could see what was happening was to replace the assertion with an if self.key not in dict_: conditional that logged a bit of debug info and then unconditionally threw an exception.

at the moment this was a mostly internal assertion, nobody has ever hit it before, so we can make more of an error message that indicates the parent mapper, that is the class that is mapped, and the attribute name.

That would probably help.

that to me seems like arbitrary information unrelated to the error being raised.

It could be. It was all contextual information that helped me track down exactly what was failing. Even when I knew which listener was being called, it wasn't clear what in the listener was actually causing the failure. The append code obviously knows something about what should and shouldn't be there, because it's performing the check.

that's not really possible here because the event has already passed.

By initiator here, I literally mean the initiator parameter. There's typically a key and an op field that helped identify a particular call in my case. You actually referenced initiator.key in your example above.

It's amusing to know that I've inherited a codebase where the very first thing I've worked on has hit a very rare error circumstance six times in one test suite. 😆

[zzzeek]

I would recommend using pdb for this case, way easier than using print statements.

Unfortunately, in this case, pdb appeared to change the behaviour of the code. I don't know if the underlying code is time sensitive, or if there's some kind of nondeterminism here, but I could consistently set a breakpoint on the assertion and, depending on how long I took looking at the data, continue execution and see the assertion succeed instead of failing. The only reliable way I could see what was happening was to replace the assertion with an if self.key not in dict_: conditional that logged a bit of debug info and then unconditionally threw an exception.

OK, what pdb will change is how many references an object has, as pdb will create strong references to the objects present in the current stack. So if your "collection loaded" issue was somehow linked to objects falling out of scope which were then being reloaded somehow, perhaps that's why pdb got in the way.

so the way to fix that problem with pdb is to not enable pdb until after the error has occurred. this is what the pdb.post_mortem() method is for. run your code in a harness that catches the assertion error being raised, then in the except: block use pdb.post_mortem() to inspect the state of things, including where you can look in the __dict__ of the object and see what's currently loaded.

that to me seems like arbitrary information unrelated to the error being raised.

It could be. It was all contextual information that helped me track down exactly what was failing. Even when I knew which listener was being called, it wasn't clear what in the listener was actually causing the failure. The append code obviously knows something about what should and shouldn't be there, because it's performing the check.

something in the listener was loading the collection. if you arent sure what, then you comment out the lines in the listener until the error goes away and that will show a clue, or you can work with things like raiseload so that the source of the lazy load of the collection produces a stack trace.

that's not really possible here because the event has already passed.

By initiator here, I literally mean the initiator parameter.

oh that, sure. that will either indicate if the event was from a backref or not, basically. that's fine