Hi Mike, Another colleague of mine sent me this write up which we believe is the root cause of our issue.
In sqlalchemy/orm/loading.py: Function _instance() defined in _instance_processor() checks if identitykey is in session_identity_map by calling session_identity_map.get(identitykey). This will return None if identitykey is in the map but the corresponding state has no obj(). _instance() then proceeds to add the new_instance to session_identity_map via session_identity_map._add_unpresent(). This will replace the existing state in identity_map with the new one. If the replaced state has a weakref to the identity map then when the replaced state is garbage collected the weakref call back will incorrectly remove the new state from the instance_map. If the new state is dirty and also in instance_map._modified then a subsequent flush can blow up in the flush_guard because the session appears dirty yet there is nothing to flush. We think your fix in https://bitbucket.org/zzzeek/sqlalchemy/issues/4068 will actually address this by avoiding cleaning up the wrong key. Does this make sense to you as well? If so we think we can just jump to 1.2.4. Thanks, Cecil On Mon, Feb 26, 2018 at 1:18 PM, Mike Bayer <mike...@zzzcomputing.com> wrote: > I can't get it to simulate your issue though. but the test case on > 4068 is pretty complicated and I don't remember how that one works > either, but it looks a lot like the safer checks post 4068 may fix the > issue. > > > > On Mon, Feb 26, 2018 at 4:06 PM, Cecil Rock <cecil.r...@gmail.com> wrote: > > OH, man sorry I misunderstood that issue. I have been starring at this > for > > too long :) > > > > Yes, that totally could be it. I'll apply that patch and should be able > to > > confirm it or not. > > > > On Mon, Feb 26, 2018 at 1:02 PM, Mike Bayer <mike...@zzzcomputing.com> > > wrote: > >> > >> On Mon, Feb 26, 2018 at 3:58 PM, Cecil Rock <cecil.r...@gmail.com> > wrote: > >> > Yeah I saw those issues, but they did not seem like they would be > >> > related to > >> > what we're seeing :( > >> > > >> > I had instrumented the identity_map earlier and could not catch an > >> > instance > >> > where it was doing the wrong thing. The GC being guilty or maybe an > >> > obscure > >> > bug higher in the stack feels more likely. It is helpful to know > that a > >> > bug > >> > doesn't come to mind with this. I'll see if I can mess with the GC > and > >> > run > >> > that to ground or not. If you have any other ideas they are much > >> > appreciated :) > >> > >> issue #4068 looks *very* likely to be related to what you are seeing. > >> I can't get your situation to reproduce with it however it is exactly > >> something that, in response to a garbage collection event, will remove > >> the *wrong* object from identity_map._dict and *keep* it in > >> identity_map._modified exactly as you are seeing. i might be able > >> to reproduce this simulating a GC against the object at a very > >> specific time during the load. > >> > >> > >> > > >> > On Mon, Feb 26, 2018 at 12:46 PM, Mike Bayer < > mike...@zzzcomputing.com> > >> > wrote: > >> >> > >> >> On Mon, Feb 26, 2018 at 3:33 PM, Cecil Rock <cecil.r...@gmail.com> > >> >> wrote: > >> >> > Fairly old, v1.0.14. Its running in one of our older > microservices. > >> >> > Once I > >> >> > understood what was going on, I went through the fix list and could > >> >> > not > >> >> > find > >> >> > anything obviously related to it. We can't reproduce this at will > >> >> > and > >> >> > nothing obvious has changed, so we're worried that upgrading > without > >> >> > understanding could just mask the issue if it exists. > >> >> > >> >> you are before the fix for > >> >> https://bitbucket.org/zzzeek/sqlalchemy/issues/4030 as well as > >> >> https://bitbucket.org/zzzeek/sqlalchemy/issues/4068 which both allow > >> >> the identity_map.discard(), safe_discard() and _fast_discard() > methods > >> >> to be safer against race conditions. you'd want to get up to > >> >> version 1.1.14 to get away from each of these issues. > >> >> > >> >> there's a lot of ways I can break certain things to produce this > error > >> >> on 1.0.14 but that same breakage still causes different errors > >> >> (because I'm purposely screwing up the internal state of things) in > >> >> later versions so I don't think I've isolated an exact race that can > >> >> cause this. > >> >> > >> >> > >> >> > >> >> > >> >> > > >> >> > On Monday, February 26, 2018 at 12:28:49 PM UTC-8, Mike Bayer > wrote: > >> >> >> > >> >> >> um what version of SQLAlchemy is this? > >> >> >> > >> >> >> On Mon, Feb 26, 2018 at 3:22 PM, Cecil Rock <cecil...@gmail.com> > >> >> >> wrote: > >> >> >> > One of my thoughts was maybe the gc wiped out the identity_map > and > >> >> >> > it > >> >> >> > gets > >> >> >> > recreated empty. > >> >> >> > > >> >> >> > Here is a stack trace of when I detect the situation prior to > the > >> >> >> > flush > >> >> >> > occurring. > >> >> >> > > >> >> >> >> [4018/eval_0/INFO/state/554/_modified_event] fc3a3a adding > >> >> >> >> <sqlalchemy.orm.state.InstanceState object at 0x7f6a5bb989e8> > as > >> >> >> >> modified > >> >> >> >> inSession:False > >> >> >> >> [4018/eval_0/ERROR/evaluate/213/runEval] Evaluate job 4c4bdfaa > >> >> >> >> caught > >> >> >> >> exception, Oh Snap (Traceback (most recent call last): > >> >> >> >> File "/home/cecil/monkey/server/app/evaluate/evaluate.py", > line > >> >> >> >> 207, > >> >> >> >> in > >> >> >> >> runEval > >> >> >> >> _evaluateMovie(params) > >> >> >> >> File "/home/cecil/monkey/server/app/evaluate/evaluate.py", > line > >> >> >> >> 196, > >> >> >> >> in > >> >> >> >> _evaluateMovie > >> >> >> >> statusDetails=evalDetails) > >> >> >> >> File "/home/cecil/monkey/server/ > app/metrics/metricsUtils.py", > >> >> >> >> line > >> >> >> >> 230, > >> >> >> >> in updateRecordableEvent > >> >> >> >> event.statusDetails = statusDetails[0:MAX_STATUS_DETAILS] > >> >> >> >> File > >> >> >> >> > >> >> >> >> > >> >> >> >> > >> >> >> >> "/home/cecil/monkey/server/venv/lib/python3.4/site- > packages/sqlalchemy/orm/attributes.py", > >> >> >> >> line 224, in __set__ > >> >> >> >> instance_dict(instance), value, None) > >> >> >> >> File > >> >> >> >> > >> >> >> >> > >> >> >> >> > >> >> >> >> "/home/cecil/monkey/server/venv/lib/python3.4/site- > packages/sqlalchemy/orm/attributes.py", > >> >> >> >> line 702, in set > >> >> >> >> state._modified_event(dict_, self, old) > >> >> >> >> File > >> >> >> >> > >> >> >> >> > >> >> >> >> > >> >> >> >> "/home/cecil/monkey/server/venv/lib/python3.4/site- > packages/sqlalchemy/orm/state.py", > >> >> >> >> line 556, in _modified_event > >> >> >> >> raise Exception('Oh Snap') > >> >> >> >> Exception: Oh Snap > >> >> >> >> ) > >> >> >> >> > >> >> >> >> This is what I'm looking at in _modified_event, this occurs > after > >> >> >> >> the > >> >> >> >> sleep in the earlier example. > >> >> >> > > >> >> >> > instance_dict = self._instance_dict() > >> >> >> > if instance_dict: > >> >> >> > # ===DEBUGGING=== > >> >> >> > if isEvent: # just check objects of interest > >> >> >> > inSession = instance_dict.contains_state( > self) > >> >> >> > logger.info('%s adding %s as modified > >> >> >> > inSession:%s', > >> >> >> > msgNum, self, inSession) > >> >> >> > if not inSession: > >> >> >> > raise Exception('Oh Snap') > >> >> >> > > >> >> >> > instance_dict._modified.add(self) > >> >> >> > > >> >> >> > Here is the stack trace if I don't catch this early > >> >> >> > > >> >> >> > [8370/eval_4/ERROR/evaluate/213/runEval] Evaluate job d498ba17 > >> >> >> > caught > >> >> >> > exception, Over 100 subsequent flushes have occurred within > >> >> >> > session.commit() > >> >> >> > - is an after_flush() hook creating new objects? (Traceback > (most > >> >> >> > recent > >> >> >> > call last): > >> >> >> > File "/home/cecil/monkey/server/app/evaluate/evaluate.py", > line > >> >> >> > 207, > >> >> >> > in > >> >> >> > runEval > >> >> >> > _evaluateMovie(params) > >> >> >> > File "/home/cecil/monkey/server/app/evaluate/evaluate.py", > line > >> >> >> > 196, > >> >> >> > in > >> >> >> > _evaluateMovie > >> >> >> > statusDetails=evalDetails) > >> >> >> > File "/home/cecil/monkey/server/app/metrics/metricsUtils.py", > >> >> >> > line > >> >> >> > 288, in > >> >> >> > updateRecordableEvent > >> >> >> > addNotifEvent(event, > >> >> >> > workflowSequence=jobParams.get('workflowSequence')) > >> >> >> > File "/home/cecil/monkey/server/app/notification/notifUtils. > py", > >> >> >> > line > >> >> >> > 93, > >> >> >> > in addNotifEvent > >> >> >> > db.session.commit() > >> >> >> > File > >> >> >> > > >> >> >> > > >> >> >> > > >> >> >> > "/home/cecil/monkey/server/venv/lib/python3.4/site- > packages/sqlalchemy/orm/scoping.py", > >> >> >> > line 157, in do > >> >> >> > return getattr(self.registry(), name)(*args, **kwargs) > >> >> >> > File > >> >> >> > > >> >> >> > > >> >> >> > > >> >> >> > "/home/cecil/monkey/server/venv/lib/python3.4/site- > packages/sqlalchemy/orm/session.py", > >> >> >> > line 822, in commit > >> >> >> > self.transaction.commit() > >> >> >> > File > >> >> >> > > >> >> >> > > >> >> >> > > >> >> >> > "/home/cecil/monkey/server/venv/lib/python3.4/site- > packages/sqlalchemy/orm/session.py", > >> >> >> > line 400, in commit > >> >> >> > self._prepare_impl() > >> >> >> > File > >> >> >> > > >> >> >> > > >> >> >> > > >> >> >> > "/home/cecil/monkey/server/venv/lib/python3.4/site- > packages/sqlalchemy/orm/session.py", > >> >> >> > line 383, in _prepare_impl > >> >> >> > "Over 100 subsequent flushes have occurred within " > >> >> >> > sqlalchemy.orm.exc.FlushError: Over 100 subsequent flushes have > >> >> >> > occurred > >> >> >> > within session.commit() - is an after_flush() hook creating new > >> >> >> > objects? > >> >> >> > > >> >> >> > > >> >> >> > > >> >> >> > > >> >> >> > > >> >> >> > -- > >> >> >> > 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 a topic in > the > >> >> Google Groups "sqlalchemy" group. > >> >> To unsubscribe from this topic, visit > >> >> https://groups.google.com/d/topic/sqlalchemy/IcgPmdW6lz8/unsubscribe > . > >> >> To unsubscribe from this group and all its topics, 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. > >> > > >> > > >> > > >> > > >> > -- > >> > - Cecil > >> > > >> > -- > >> > 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 a topic in the > >> Google Groups "sqlalchemy" group. > >> To unsubscribe from this topic, visit > >> https://groups.google.com/d/topic/sqlalchemy/IcgPmdW6lz8/unsubscribe. > >> To unsubscribe from this group and all its topics, 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. > > > > > > > > > > -- > > - Cecil > > > > -- > > 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 a topic in the > Google Groups "sqlalchemy" group. > To unsubscribe from this topic, visit https://groups.google.com/d/ > topic/sqlalchemy/IcgPmdW6lz8/unsubscribe. > To unsubscribe from this group and all its topics, 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. > -- - Cecil -- 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.
