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 <[email protected]> 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 <[email protected]> > wrote: >> >> On Mon, Feb 26, 2018 at 3:58 PM, Cecil Rock <[email protected]> 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 <[email protected]> >> > wrote: >> >> >> >> On Mon, Feb 26, 2018 at 3:33 PM, Cecil Rock <[email protected]> >> >> 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 <[email protected]> >> >> >> 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 [email protected]. >> >> >> > To post to this group, send email to [email protected]. >> >> >> > 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 [email protected]. >> >> > To post to this group, send email to [email protected]. >> >> > 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 >> >> [email protected]. >> >> To post to this group, send email to [email protected]. >> >> 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 [email protected]. >> > To post to this group, send email to [email protected]. >> > 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 >> [email protected]. >> To post to this group, send email to [email protected]. >> 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 [email protected]. > To post to this group, send email to [email protected]. > 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 [email protected]. To post to this group, send email to [email protected]. Visit this group at https://groups.google.com/group/sqlalchemy. For more options, visit https://groups.google.com/d/optout.
