Thanks a lot. I'll test this patch in our environment.
在 2018年5月16日星期三 UTC+8上午2:58:56，Mike Bayer写道： > > good news, I reproduced it. > > Even better news for you, vindication! nothing to do with greenlets, > threads, concurrency, or anything (though it doesn't have to do with > the "del" or the weakref, this is much simpler ). > > This has to do with a special rule in the pool when there is a > so-called "reset agent" involved that cleans up a pooled connection > while taking into account the fact that the enclosing Connection had a > transaction in progress. That is introducing the > _handle_error()->invalidate() routine *inside* the normal > _finalize_fairy routine and that is why we see _finalize_fairy twice. > The _finalize_fairy we see that seems to start in the middle of the > operation is called first, then the _finalize_fairy we see failing is > inside of that. So they aren't sibling operations, they are nested. > > > https://bitbucket.org/zzzeek/sqlalchemy/issues/4252/double-checkin-due-to-handle_error-called > > > > > On Tue, May 15, 2018 at 1:26 PM, Mike Bayer <[email protected] > <javascript:>> wrote: > > can you add these lines to your logging, ensure that the check for > > "already in pool" is present, and produce new logs? > > > > try: > > fairy = fairy or _ConnectionFairy( > > connection, connection_record, echo) > > assert fairy.connection is connection > > pool.logger.debug("ABOUT TO RESET CONNECTION %s CONNECTION > > REC %s FAIRY %s", connection, fairy, connection_record) > > fairy._reset(pool) > > pool.logger.debug("COMPLETED RESET CONNECTION %s > > CONNECTION REC %s FAIRY %s", connection, fairy, connection_record) > > > > # Immediately close detached instances > > if not connection_record: > > pool._close_connection(connection) > > except BaseException as e: > > pool.logger.debug("EXCEPTION RAISED IN RESET CONNECTION %s > > CONNECTION REC %s FAIRY %s: %s", connection, fairy, connection_record, > > e) > > pool.logger.error( > > "Exception during reset or similar", exc_info=True) > > if connection_record: > > pool.logger.debug("jjs going to > connection_record.invalidate") > > connection_record.invalidate(e=e) > > if not isinstance(e, Exception): > > pool.logger.debug("jjs e %s is not Exception, raise > again", e) > > raise > > > > my current theory is that a greenlet is being blocked in _reset(), > > then waking up later but is being corrupted at the greenlet level in > > some way. > > > > > > > > On Tue, May 15, 2018 at 12:15 PM, Mike Bayer <[email protected] > <javascript:>> wrote: > >> > >> > >> On Tue, May 15, 2018, 3:26 AM <[email protected] <javascript:>> > wrote: > >>> > >>> We got the log "jjs _finalize_fairy args" just once but the code in > >>> function _finalize_fairy seem to be called twice. It also confused me. > >> > >> > >> It's because that code originated elsewhere and got blocked, then it > picks > >> up again but the callstack is somehow corrupted (or logging isn't > telling > >> the truth). > >> > >> Can you please give me: > >> > >> Exact version of eventlet in use > >> Exact version of psycopg2 and psyco-green > >> Exact python interpreter version > >> Exact version of SQLAlchemy > >> Exact version of Oslo.db > >> > >> Thanks > >> > >> > >> > >>> > >>> BTW, I tried to add code[1] to avoid double checkin in _finalize_fairy > but > >>> failed. > >>> That means the code in pool.py#L670-692 was called without L646-668. > >>> > >>> [1] https://github.com/jiajunsu/test_logs/blob/master/pool.py#L659 > >>> > >>> 在 2018年5月15日星期二 UTC+8下午12:41:17，Mike Bayer写道： > >>>> > >>>> s > >>>> > >>>> > >>>> > >>>> On Mon, May 14, 2018 at 9:38 PM, <[email protected]> wrote: > >>>> > The tid is coroutine_id, we get it by id(greenlet.getcurrent()) in > each > >>>> > coroutine(green thread). > >>>> > > >>>> > We run nova-conductor with monkey_patch, the same as [1], > >>>> > eventlet.monkey_patch(os=False) > >>>> > > >>>> > Our nova-conductor is running with multi workers. > >>>> > > >>>> > It's confusing why the _finalize_fairy is called twice but only log > >>>> > once at > >>>> > the entrance, that's why I guess it's called by weakref's callback. > >>>> > >>>> For 130446032 which is the tid you mentioned, _finalize_fairy is only > >>>> called once in your log: > >>>> > >>>> $ cat nc_5679.log | grep -e "130446032.*jjs _finalize" > >>>> 2018-05-14T11:11:39.955+08:00 localhost nova-conductor DEBUG > >>>> [pid:5679] [MainThread] [tid:130446032] [log.py:104 debug] > >>>> [req-841bb432-7cd2-4fa3-9def-559a34b05a21] jjs _finalize_fairy args > >>>> conn None, rec.conn None, rec, <sqlalchemy.pool._ConnectionRecord > >>>> object at 0x70cdb10>. ref None, fairy > >>>> <sqlalchemy.pool._ConnectionFairy object at 0x8a87390> debug > >>>> > >>>> Also, the log shows that no _finalize_fairy is ever called due to > >>>> "del" - this would show the weakref "ref" as non-None: > >>>> > >>>> $ cat nc_5679.log | grep -e "FINALIZE FAIRY.*REF:.*" | grep -v "REF: > >>>> None" > >>>> $ > >>>> > >>>> I would assume by "finalize fairy" called twice, you're referring to > >>>> the fact that you see the "exception during reset or simlar" message. > >>>> But that message is still AFAICT impossible to be emitted without the > >>>> function being entered, and a corresponding "FINALIZE FAIRY" log line > >>>> preceding it, unless something is going wrong with the logging, or > the > >>>> interpreter is somehow not functioning correctly (I wonder if > eventlet > >>>> had any such issues). I'm struggling to see any other possibility > >>>> but not coming up with any. > >>>> > >>>> One weird thing I'm trying to figure out is that I see a connection > >>>> being returned to the pool normally, but then nothing is logged about > >>>> it after that: > >>>> > >>>> 2018-05-14T11:11:21.183+08:00 localhost nova-conductor DEBUG > >>>> [pid:5679] [MainThread] [tid:130446352] [log.py:104 debug] > >>>> [req-19a57f61-bc64-4575-8253-00b5bfe62a74] Connection <connection > >>>> object at 0x7f419c0; closed: 0> being returned to pool, > >>>> connection_record.connection <connection object at 0x7f419c0; closed: > >>>> 0> debug > >>>> > >>>> > >>>> the next log message from tid:130446352 should be "jjs conn reset". > >>>> But that never happens. The next we see of that tid is: > >>>> > >>>> 2018-05-14T11:11:21.549+08:00 localhost nova-conductor DEBUG > >>>> [pid:5679] [MainThread] [tid:130446352] [log.py:104 debug] > >>>> [req-0ef61146-5cb6-4f46-9788-406b6d376843] jjs > >>>> _ConnectionFairy._checkout fariy None debug > >>>> 2018-05-14T11:11:21.549+08:00 localhost nova-conductor DEBUG > >>>> [pid:5679] [MainThread] [tid:130446352] [log.py:104 debug] > >>>> [req-0ef61146-5cb6-4f46-9788-406b6d376843] jjs before pool._do_get > >>>> pool queue deque([<sqlalchemy.pool._ConnectionRecord object at > >>>> 0x7777e10>, <sqlalchemy.pool._ConnectionRecord object at 0x75fb7d0>, > >>>> <sqlalchemy.pool._ConnectionRecord object at 0x778d810>, > >>>> <sqlalchemy.pool._ConnectionRecord object at 0x7600610>, > >>>> <sqlalchemy.pool._ConnectionRecord object at 0x6ea7e10>, > >>>> <sqlalchemy.pool._ConnectionRecord object at 0x7798050>, > >>>> <sqlalchemy.pool._ConnectionRecord object at 0x796d110>, > >>>> <sqlalchemy.pool._ConnectionRecord object at 0x7798d50>, > >>>> <sqlalchemy.pool._ConnectionRecord object at 0x75f5710>]) debug > >>>> > >>>> that is, it's checking out a new connection ? If it were blocking on > >>>> trying to reset the connection, we wouldn't see that tid again. I > >>>> wonder if the greenlet was interrupted or something. I'm finding > >>>> various impossibilities like this going on and not able to come up > >>>> with any theory other than the interpreter is somehow not functioning > >>>> correcltly, or the logging here is somehow incomplete. > >>>> > >>>> I notice you're on a very old version of SQLAlchemy (three years > old). > >>>> You really should be on at least the 1.1 series because for > >>>> greenlets you need to have: > >>>> > >>>> > http://docs.sqlalchemy.org/en/latest/changelog/migration_11.html#change-3803. > > >>>> > >>>> > >>>> > >>>> > >>>> > >>>> > >>>> > >>>> > >>>> > > >>>> > [1] > https://github.com/openstack/nova/blob/master/nova/cmd/__init__.py > >>>> > > >>>> > > >>>> > 在 2018年5月14日星期一 UTC+8下午11:59:43，Mike Bayer写道： > >>>> >> > >>>> >> I notice in this log file there are multiple "tid", which I assume > to > >>>> >> be thread identifiers ? E.g. OS-level threads? Are you using > >>>> >> eventlet or not? Are you monkeypatching SQLAlchemy and then > using > >>>> >> multiple OS-level threads at the same time? Because that likely > >>>> >> doesn't work. > >>>> >> > >>>> >> Particularly, the log here illustrates an impossible codepath. > >>>> >> > >>>> >> We enter finalize_fairy with connection is None: > >>>> >> > >>>> >> 2018-05-14T11:11:39.961+08:00 localhost nova-conductor DEBUG > >>>> >> [pid:5679] [MainThread] [tid:130446352] [log.py:104 debug] > >>>> >> [req-74ef6531-2d92-40ea-a524-f54e11edab06] FINALIZE FAIRY: DB > CONN: > >>>> >> None, FAIRY: <sqlalchemy.pool._ConnectionFairy object at > 0x87dd3d0>, > >>>> >> REF: None CONNECTION_REC: <sqlalchemy.pool._ConnectionRecord > object > >>>> >> at 0x776fe90> CONNECTION_REC REF <weakref at 0x7c5cdb8; to > >>>> >> '_ConnectionFairy' at 0x87dd3d0> debug > >>>> >> > >>>> >> this seems to make it through to the checkin at the bottom. > >>>> >> > >>>> >> Then, we see this: > >>>> >> > >>>> >> 2018-05-14T11:11:39.968+08:00 localhost nova-conductor ERROR > >>>> >> [pid:5679] [MainThread] [tid:130446032] [log.py:122 error] > >>>> >> [req-841bb432-7cd2-4fa3-9def-559a34b05a21] Exception during reset > or > >>>> >> similar > >>>> >> > >>>> >> The only place that message is generated is *in* finalize_fairy, > >>>> >> *before* the checkin occurs, and *only* if _finalize_fairy was > called > >>>> >> *with* a connection that is non -None. There is no other call > >>>> >> _finalize_fairy with that request identifier, therefore I see no > >>>> >> evidence of where this message "exception during reset" can be > >>>> >> generated from - there would at least need to be an additional log > >>>> >> line with "FINALIZE FAIRY" and the connection non-None for this to > be > >>>> >> reached. I see no way that the pool.py shipped with SQLAlchemy > can > >>>> >> possibly generate this series of steps. > >>>> >> > >>>> >> This is an extremely intricate issue and I still have only the > vaguest > >>>> >> notion of how you are running SQLAlchemy / Nova. > >>>> >> > >>>> >> > >>>> >> > >>>> >> > >>>> >> On Mon, May 14, 2018 at 11:10 AM, Mike Bayer < > [email protected]> > >>>> >> wrote: > >>>> >> > OK I need the exact pool.py you are using as well that includes > all > >>>> >> > these logging statements and any other adjustments that were > made. > >>>> >> > > >>>> >> > > >>>> >> > > >>>> >> > On Mon, May 14, 2018 at 8:02 AM, <[email protected]> wrote: > >>>> >> >> I've uploaded the logs here: > >>>> >> >> > >>>> >> >> > https://raw.githubusercontent.com/jiajunsu/test_logs/master/nc_5679.log > >>>> >> >> > >>>> >> >> The ConnectionRecord is 0x70cdb10, tid(coroutine id) is > 130446032 > >>>> >> >> > >>>> >> >> At 2018-05-14T11:11:39.970, we got the log " jjs rec already > in > >>>> >> >> pool > >>>> >> >> checkin", but I just deleted `return` in code, so the problem > >>>> >> >> happen > >>>> >> >> again. > >>>> >> >> > >>>> >> >> > >>>> >> >> > >>>> >> >> > >>>> >> >> 在 2018年5月14日星期一 UTC+8上午10:48:49，Mike Bayer写道： > >>>> >> >>> > >>>> >> >>> as well as the log that shows this: > >>>> >> >>> > >>>> >> >>> + if self in pool._pool.queue: > >>>> >> >>> + pool.logger.debug("jjs rec already in pool checkin, > skip > >>>> >> >>> %r", > >>>> >> >>> self) > >>>> >> >>> + return > >>>> >> >>> > >>>> >> >>> > >>>> >> >>> actually happening. > >>>> >> >>> > >>>> >> >>> > >>>> >> >>> > >>>> >> >>> > >>>> >> >>> On Sun, May 13, 2018 at 10:42 PM, Mike Bayer > >>>> >> >>> <[email protected]> > >>>> >> >>> wrote: > >>>> >> >>> > On Sun, May 13, 2018 at 10:35 PM, <[email protected]> > wrote: > >>>> >> >>> >> "jjs" is short for my name and "cjr" is my > colleague's(JinRong > >>>> >> >>> >> Cai). We > >>>> >> >>> >> work > >>>> >> >>> >> together and add logs in the same environment, add prefix > of > >>>> >> >>> >> name > >>>> >> >>> >> to > >>>> >> >>> >> get a > >>>> >> >>> >> keyword for log filter. > >>>> >> >>> >> > >>>> >> >>> >> The doubled ConnectionRecords(with None connection) are got > by > >>>> >> >>> >> two > >>>> >> >>> >> different > >>>> >> >>> >> coroutines, and the variable record.connection is rewrite > by > >>>> >> >>> >> the > >>>> >> >>> >> second > >>>> >> >>> >> coroutines. > >>>> >> >>> >> After the record being put back to QueuePool again, there > are > >>>> >> >>> >> two > >>>> >> >>> >> same > >>>> >> >>> >> record with same connection in the pool, which will cause > the > >>>> >> >>> >> next > >>>> >> >>> >> two > >>>> >> >>> >> coroutines get conflict and deadlock in psycopg2 as above. > >>>> >> >>> > > >>>> >> >>> > OK, I need the detailed step by step that shows how the two > >>>> >> >>> > coroutines > >>>> >> >>> > are interacting such that they both are returning the same > >>>> >> >>> > connection. > >>>> >> >>> > The nova log above seems to show just one coroutine I > assume > >>>> >> >>> > since > >>>> >> >>> > there is just one nova request ID, if I understand > correctly. > >>>> >> >>> > > >>>> >> >>> >> > >>>> >> >>> >> The logs of psycopg2 has been pasted at > >>>> >> >>> >> https://github.com/psycopg/psycopg2/issues/703 > >>>> >> >>> > > >>>> >> >>> > The above issue says the bug has been found in SQLAlchemy > but > >>>> >> >>> > there > >>>> >> >>> > is > >>>> >> >>> > no bug report yet and I've not yet been shown how the > behavior > >>>> >> >>> > here > >>>> >> >>> > is > >>>> >> >>> > possible. I posted a straightforward example above, can > you > >>>> >> >>> > please show me where the two coroutines get mixed up ? > >>>> >> >>> > > >>>> >> >>> > > >>>> >> >>> > > >>>> >> >>> > > >>>> >> >>> >> > >>>> >> >>> >> > >>>> >> >>> >> > >>>> >> >>> >> 在 2018年5月11日星期五 UTC+8上午3:05:46，Mike Bayer写道： > >>>> >> >>> >>> > >>>> >> >>> >>> I tried to follow your log lines, which is difficult > because I > >>>> >> >>> >>> don't > >>>> >> >>> >>> know where those log statements actually are and I don't > know > >>>> >> >>> >>> what > >>>> >> >>> >>> acronyms like "jjs", "cjr", mean. But it does look like > it's > >>>> >> >>> >>> al > >>>> >> >>> >>> in > >>>> >> >>> >>> one thread (so not async GC) and all in one Nova request > (so > >>>> >> >>> >>> perhaps > >>>> >> >>> >>> just one greenlet involved, unless other greenlets are > >>>> >> >>> >>> affecting > >>>> >> >>> >>> this > >>>> >> >>> >>> without them being displayed in this log snippet). I do > see > >>>> >> >>> >>> the > >>>> >> >>> >>> connection record doubled at the end. So here is the > >>>> >> >>> >>> illustration of > >>>> >> >>> >>> those steps in isolation, the connection record is not > >>>> >> >>> >>> doubled. > >>>> >> >>> >>> Can > >>>> >> >>> >>> you alter this program to show this condition occurring? > >>>> >> >>> >>> > >>>> >> >>> >>> from sqlalchemy import create_engine > >>>> >> >>> >>> > >>>> >> >>> >>> e = > create_engine("postgresql://scott:tiger@localhost/test", > >>>> >> >>> >>> echo_pool='debug') > >>>> >> >>> >>> e.connect().close() > >>>> >> >>> >>> > >>>> >> >>> >>> assert len(e.pool._pool.queue) == 1 > >>>> >> >>> >>> > >>>> >> >>> >>> c1 = e.connect() > >>>> >> >>> >>> > >>>> >> >>> >>> assert len(e.pool._pool.queue) == 0 > >>>> >> >>> >>> > >>>> >> >>> >>> c1.engine.pool._invalidate(c1._Connection__connection, > None) > >>>> >> >>> >>> c1.invalidate(e) > >>>> >> >>> >>> > >>>> >> >>> >>> # connection record is back > >>>> >> >>> >>> assert len(e.pool._pool.queue) == 1 > >>>> >> >>> >>> > >>>> >> >>> >>> # do a reconnect > >>>> >> >>> >>> c1.connection > >>>> >> >>> >>> > >>>> >> >>> >>> # uses the record again > >>>> >> >>> >>> assert len(e.pool._pool.queue) == 0 > >>>> >> >>> >>> > >>>> >> >>> >>> # close the Connection > >>>> >> >>> >>> c1.close() > >>>> >> >>> >>> > >>>> >> >>> >>> # record is back > >>>> >> >>> >>> assert len(e.pool._pool.queue) == 1 > >>>> >> >>> >>> > >>>> >> >>> >>> # etc. > >>>> >> >>> >>> c1 = e.connect() > >>>> >> >>> >>> assert len(e.pool._pool.queue) == 0 > >>>> >> >>> >>> > >>>> >> >>> >>> c1.close() > >>>> >> >>> >>> assert len(e.pool._pool.queue) == 1 > >>>> >> >>> >>> > >>>> >> >>> >>> > >>>> >> >>> >>> > >>>> >> >>> >>> > >>>> >> >>> >>> On Thu, May 10, 2018 at 12:25 PM, Mike Bayer > >>>> >> >>> >>> <[email protected]> > >>>> >> >>> >>> wrote: > >>>> >> >>> >>> > Here's a print statement you might want to try: > >>>> >> >>> >>> > > >>>> >> >>> >>> > diff --git a/lib/sqlalchemy/pool.py > b/lib/sqlalchemy/pool.py > >>>> >> >>> >>> > index 89a4cea7c..452db4883 100644 > >>>> >> >>> >>> > --- a/lib/sqlalchemy/pool.py > >>>> >> >>> >>> > +++ b/lib/sqlalchemy/pool.py > >>>> >> >>> >>> > @@ -689,6 +689,19 @@ def _finalize_fairy(connection, > >>>> >> >>> >>> > connection_record, > >>>> >> >>> >>> > been garbage collected. > >>>> >> >>> >>> > > >>>> >> >>> >>> > """ > >>>> >> >>> >>> > + print( > >>>> >> >>> >>> > + "FINALIZE FAIRY: GREENLET ID: %s, DB CONN: %s, > >>>> >> >>> >>> > FAIRY: > >>>> >> >>> >>> > %s, > >>>> >> >>> >>> > REF: > >>>> >> >>> >>> > %s " > >>>> >> >>> >>> > + "CONNECTION_REC: %s CONNECTION_REC REF %s" % ( > >>>> >> >>> >>> > + "put greenlet id here", > >>>> >> >>> >>> > + connection, > >>>> >> >>> >>> > + fairy, > >>>> >> >>> >>> > + ref, > >>>> >> >>> >>> > + connection_record, > >>>> >> >>> >>> > + connection_record.fairy_ref > >>>> >> >>> >>> > + if connection_record is not None else "n/a" > >>>> >> >>> >>> > + ) > >>>> >> >>> >>> > + ) > >>>> >> >>> >>> > + > >>>> >> >>> >>> > _refs.discard(connection_record) > >>>> >> >>> >>> > > >>>> >> >>> >>> > if ref is not None: > >>>> >> >>> >>> > > >>>> >> >>> >>> > > >>>> >> >>> >>> > > >>>> >> >>> >>> > > >>>> >> >>> >>> > > >>>> >> >>> >>> > On Thu, May 10, 2018 at 12:21 PM, Mike Bayer > >>>> >> >>> >>> > <[email protected]> > >>>> >> >>> >>> > wrote: > >>>> >> >>> >>> >> On Thu, May 10, 2018 at 7:23 AM, <[email protected]> > > >>>> >> >>> >>> >> wrote: > >>>> >> >>> >>> >>> Hi Mike, > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> I added more logs and finnaly find the reason and a > method > >>>> >> >>> >>> >>> to > >>>> >> >>> >>> >>> avoid > >>>> >> >>> >>> >>> the > >>>> >> >>> >>> >>> deadlock between coroutines. > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> In summary, the deadlock happend because two different > >>>> >> >>> >>> >>> coroutines > >>>> >> >>> >>> >>> use > >>>> >> >>> >>> >>> the > >>>> >> >>> >>> >>> same ConnectionRecord with same connection. > >>>> >> >>> >>> >>> It happends under QueuePool, when the DB connections > are > >>>> >> >>> >>> >>> reset > >>>> >> >>> >>> >>> by > >>>> >> >>> >>> >>> the > >>>> >> >>> >>> >>> DB > >>>> >> >>> >>> >>> server(not related with the backend driver). > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> 1.A coroutine get a ConnectionRecord into > ConnectionFairy, > >>>> >> >>> >>> >>> and > >>>> >> >>> >>> >>> apply a > >>>> >> >>> >>> >>> weakref of the ConnectionFairy, with callback function > >>>> >> >>> >>> >>> `_finalize_fairy`. > >>>> >> >>> >>> >>> 2.When the connection get disconnected, it receives an > >>>> >> >>> >>> >>> exception(psycopg2.OperationalError), and goto > >>>> >> >>> >>> >>> Connection._handle_dbapi_exception. > >>>> >> >>> >>> >>> 3.In `_handle_dbapi_exception.finnaly`, it will call > both > >>>> >> >>> >>> >>> `ConnectionFairy.invalidate` and `self.invalidate`. > >>>> >> >>> >>> >>> 4.In `ConnectionFairy.invalidate`, > >>>> >> >>> >>> >>> `_ConnectionRecord._checkin` is > >>>> >> >>> >>> >>> called, > >>>> >> >>> >>> >>> and put the ConnectionRecord back to the QueuePool. > >>>> >> >>> >>> >>> 5.In `self.invalidate`, `del self._root.__connection` > is > >>>> >> >>> >>> >>> called, > >>>> >> >>> >>> >>> and > >>>> >> >>> >>> >>> **del** > >>>> >> >>> >>> >>> the ConnectionFairy. > >>>> >> >>> >>> >>> 6.The **del** operation will make weakref of > >>>> >> >>> >>> >>> ConnectionFairy > >>>> >> >>> >>> >>> to > >>>> >> >>> >>> >>> dead, > >>>> >> >>> >>> >>> and > >>>> >> >>> >>> >>> the callback `_finalize_fairy` executed. > >>>> >> >>> >>> >>> 7.In `_finalize_fairy`, another > >>>> >> >>> >>> >>> `_ConnectionRecord._checkin` > >>>> >> >>> >>> >>> is > >>>> >> >>> >>> >>> called, put > >>>> >> >>> >>> >>> the ConnectionRecord to the QueuePool again. > >>>> >> >>> >>> >> > >>>> >> >>> >>> >> Here's what does not make sense. You are claiming that > a > >>>> >> >>> >>> >> simple > >>>> >> >>> >>> >> invalidation will result in the same ConnectionRecord > being > >>>> >> >>> >>> >> checked > >>>> >> >>> >>> >> in > >>>> >> >>> >>> >> twice. This is obviously not the case, what is > special in > >>>> >> >>> >>> >> your > >>>> >> >>> >>> >> situation that makes this happen? > >>>> >> >>> >>> >> > >>>> >> >>> >>> >> If I follow the steps you refer towards, in step 4, > when > >>>> >> >>> >>> >> ConnectionFairy._checkin is called, that calls > >>>> >> >>> >>> >> finalize_fairy > >>>> >> >>> >>> >> directly, which then calls ConnectionRecord.checkin(). > >>>> >> >>> >>> >> Within > >>>> >> >>> >>> >> ConnectionRecord.checkin(), ConnectionRecord.fairy_ref > is > >>>> >> >>> >>> >> set > >>>> >> >>> >>> >> to > >>>> >> >>> >>> >> None. > >>>> >> >>> >>> >> Then back in ConnectionFairy._checkin(), it also > sets > >>>> >> >>> >>> >> self._connection_record = None. > >>>> >> >>> >>> >> > >>>> >> >>> >>> >> If we come back into finalize_fairy a *second* time > then, > >>>> >> >>> >>> >> as a > >>>> >> >>> >>> >> result > >>>> >> >>> >>> >> of the "del" which occurs in _handle_error(), and the > >>>> >> >>> >>> >> connection_record is present, the function will exit > >>>> >> >>> >>> >> immediately, > >>>> >> >>> >>> >> because: > >>>> >> >>> >>> >> > >>>> >> >>> >>> >> if connection_record.fairy_ref is not ref: > >>>> >> >>> >>> >> return > >>>> >> >>> >>> >> > >>>> >> >>> >>> >> So the situation as given is not possible without > >>>> >> >>> >>> >> concurrent > >>>> >> >>> >>> >> access > >>>> >> >>> >>> >> to > >>>> >> >>> >>> >> the ConnectionFairy being introduced externally to the > >>>> >> >>> >>> >> pool. > >>>> >> >>> >>> >> > >>>> >> >>> >>> >> There is exactly one thing I can think of that is both > >>>> >> >>> >>> >> unique > >>>> >> >>> >>> >> to > >>>> >> >>> >>> >> the > >>>> >> >>> >>> >> psycopg2-style of asynchronous connection, not the > PyMySQL > >>>> >> >>> >>> >> form > >>>> >> >>> >>> >> of > >>>> >> >>> >>> >> it, > >>>> >> >>> >>> >> that might be important here, and it's that I think > >>>> >> >>> >>> >> psycopg2's > >>>> >> >>> >>> >> connection.close() method will defer to another > greenlet. > >>>> >> >>> >>> >> That > >>>> >> >>> >>> >> means > >>>> >> >>> >>> >> when we're inside of ConnectionRecord.invalidate(), and > we > >>>> >> >>> >>> >> call > >>>> >> >>> >>> >> self.__close(), that could be deferring to another > >>>> >> >>> >>> >> greenlet. > >>>> >> >>> >>> >> But > >>>> >> >>> >>> >> this all happens before the connection is returned to > the > >>>> >> >>> >>> >> pool, > >>>> >> >>> >>> >> so > >>>> >> >>> >>> >> I > >>>> >> >>> >>> >> still don't know what is happening. > >>>> >> >>> >>> >> > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> The logs in detail is below. To prove my result is > right, > >>>> >> >>> >>> >>> I > >>>> >> >>> >>> >>> tried > >>>> >> >>> >>> >>> to > >>>> >> >>> >>> >>> avoid > >>>> >> >>> >>> >>> the scienario with this patch, and it worked. > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> def checkin(self): > >>>> >> >>> >>> >>> self.fairy_ref = None > >>>> >> >>> >>> >>> connection = self.connection > >>>> >> >>> >>> >>> pool = self.__pool > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> while self.finalize_callback: > >>>> >> >>> >>> >>> finalizer = self.finalize_callback.pop() > >>>> >> >>> >>> >>> finalizer(connection) > >>>> >> >>> >>> >>> + if self in pool._pool.queue: > >>>> >> >>> >>> >>> + pool.logger.debug("jjs rec already in pool > >>>> >> >>> >>> >>> checkin, > >>>> >> >>> >>> >>> skip > >>>> >> >>> >>> >>> %r", > >>>> >> >>> >>> >>> self) > >>>> >> >>> >>> >>> + return > >>>> >> >>> >>> >> > >>>> >> >>> >>> >> as mentioned above it's not possible to reach this > point > >>>> >> >>> >>> >> without > >>>> >> >>> >>> >> concurrent access to the pooled connection, which means > >>>> >> >>> >>> >> this > >>>> >> >>> >>> >> fix > >>>> >> >>> >>> >> could > >>>> >> >>> >>> >> fail also (with at least threaded-style concurrency, > not > >>>> >> >>> >>> >> greenlet > >>>> >> >>> >>> >> style). The original source of the greenlet issue > must > >>>> >> >>> >>> >> still > >>>> >> >>> >>> >> be > >>>> >> >>> >>> >> identified. > >>>> >> >>> >>> >> > >>>> >> >>> >>> >> I would need a self-contained proof of concept that > >>>> >> >>> >>> >> demonstrates > >>>> >> >>> >>> >> this > >>>> >> >>> >>> >> issue occurring. The log output is not that helpful > >>>> >> >>> >>> >> because it > >>>> >> >>> >>> >> at > >>>> >> >>> >>> >> least would need to write out the identifier of the > current > >>>> >> >>> >>> >> greenlet, > >>>> >> >>> >>> >> since it is very likely that greenlets have something > to do > >>>> >> >>> >>> >> with > >>>> >> >>> >>> >> this > >>>> >> >>> >>> >> issue. > >>>> >> >>> >>> >> > >>>> >> >>> >>> >> > >>>> >> >>> >>> >> > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> if pool.dispatch.checkin: > >>>> >> >>> >>> >>> pool.dispatch.checkin(connection, self) > >>>> >> >>> >>> >>> pool._return_conn(self) > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> Trace the ConnectionRecord 0x88fc5d0 > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> 2018-05-10T14:02:17.927+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] Created new > >>>> >> >>> >>> >>> connection > >>>> >> >>> >>> >>> <connection object at 0x81f69b0; closed: 0> > >>>> >> >>> >>> >>> 2018-05-10T14:02:17.928+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs get > conn > >>>> >> >>> >>> >>> success > >>>> >> >>> >>> >>> <connection > >>>> >> >>> >>> >>> object at 0x81f69b0; closed: 0>, rec.connection > >>>> >> >>> >>> >>> <connection > >>>> >> >>> >>> >>> object > >>>> >> >>> >>> >>> at > >>>> >> >>> >>> >>> 0x81f69b0; closed: 0>, pool queue > >>>> >> >>> >>> >>> deque([<sqlalchemy.pool._ConnectionRecord > >>>> >> >>> >>> >>> object at 0x7a04810>, > <sqlalchemy.pool._ConnectionRecord > >>>> >> >>> >>> >>> object at > >>>> >> >>> >>> >>> 0x79fdad0>]) > >>>> >> >>> >>> >>> 2018-05-10T14:02:17.929+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs > checkout > >>>> >> >>> >>> >>> fairy > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionFairy object at 0x329c0d0> > rec > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x88fc5d0> > >>>> >> >>> >>> >>> pool > >>>> >> >>> >>> >>> queue > >>>> >> >>> >>> >>> deque([<sqlalchemy.pool._ConnectionRecord object at > >>>> >> >>> >>> >>> 0x7a04810>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x79fdad0>]) > >>>> >> >>> >>> >>> 2018-05-10T14:02:17.929+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] Connection > >>>> >> >>> >>> >>> <connection > >>>> >> >>> >>> >>> object at > >>>> >> >>> >>> >>> 0x81f69b0; closed: 0> checked out from pool, status > Pool > >>>> >> >>> >>> >>> size: > >>>> >> >>> >>> >>> 10 > >>>> >> >>> >>> >>> Connections in pool: 2 Current Overflow: 0 Max > Overflow: > >>>> >> >>> >>> >>> 40 > >>>> >> >>> >>> >>> Current > >>>> >> >>> >>> >>> Checked > >>>> >> >>> >>> >>> out connections: 8, queue > >>>> >> >>> >>> >>> deque([<sqlalchemy.pool._ConnectionRecord > >>>> >> >>> >>> >>> object > >>>> >> >>> >>> >>> at 0x7a04810>, <sqlalchemy.pool._ConnectionRecord > object > >>>> >> >>> >>> >>> at > >>>> >> >>> >>> >>> 0x79fdad0>]) > >>>> >> >>> >>> >>> 2018-05-10T14:02:17.930+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs > >>>> >> >>> >>> >>> _ConnectionFairy._checkout > >>>> >> >>> >>> >>> conn <connection object at 0x81f69b0; closed: 0>, rec > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x88fc5d0>, > >>>> >> >>> >>> >>> rec.conn > >>>> >> >>> >>> >>> <connection object at 0x81f69b0; closed: 0> > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.716+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> ERROR > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:122 error] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] cjr error > conn > >>>> >> >>> >>> >>> <sqlalchemy.engine.base.Connection object at > 0x329c150>, > >>>> >> >>> >>> >>> err > >>>> >> >>> >>> >>> connection > >>>> >> >>> >>> >>> pointer is NULL > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.717+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> ERROR > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:122 error] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] cjr enter > >>>> >> >>> >>> >>> newraise > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.717+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> ERROR > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:122 error] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] cjr enter > >>>> >> >>> >>> >>> finally > >>>> >> >>> >>> >>>>>Connection._handle_dbapi_exception --> finally --> > >>>> >> >>> >>> >>>>> **self.engine.pool._invalidate** & > **self.invalidate** > >>>> >> >>> >>> >>>>>self.engine.pool._invalidate --> Pool._invalidate --> > >>>> >> >>> >>> >>>>> ConnectionFairy.invalidate --> > >>>> >> >>> >>> >>>>> _ConnectionRecord.invalidate > >>>> >> >>> >>> >>>>> & > >>>> >> >>> >>> >>>>> **self._checkin()** > >>>> >> >>> >>> >>>>>self.invalidate() --> **del self._root.__connection** > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.718+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs > >>>> >> >>> >>> >>> connectionFairy > >>>> >> >>> >>> >>> invalidate > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.718+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> INFO > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:109 info] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] Invalidate > >>>> >> >>> >>> >>> connection > >>>> >> >>> >>> >>> <connection > >>>> >> >>> >>> >>> object at 0x81f69b0; closed: 2> (reason: > >>>> >> >>> >>> >>> OperationalError:connection > >>>> >> >>> >>> >>> pointer > >>>> >> >>> >>> >>> is NULL > >>>> >> >>> >>> >>>>>_ConnectionRecord.invalidate(e) --> > >>>> >> >>> >>> >>>>> self.__pool.dispatch.invalidate(self.connection, > self, > >>>> >> >>> >>> >>>>> e) & > >>>> >> >>> >>> >>>>> self.__close() & > >>>> >> >>> >>> >>>>> self.connection = None > >>>> >> >>> >>> >>>>>self.__close() --> self.finalize_callback.clear() & > >>>> >> >>> >>> >>>>> self.__pool._close_connection(self.connection) > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.719+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] Closing > >>>> >> >>> >>> >>> connection > >>>> >> >>> >>> >>> <connection > >>>> >> >>> >>> >>> object at 0x81f69b0; closed: 2> > >>>> >> >>> >>> >>>>>Pool._close_connection(connection) --> > >>>> >> >>> >>> >>>>> self._dialect.do_close(connection) > >>>> >> >>> >>> >>>>> --> _ConnDialect.do_close(dbapi_connection) --> > >>>> >> >>> >>> >>>>> dbapi_connection.close() FIN > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.719+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs > >>>> >> >>> >>> >>> _ConnectionFairy._checkin > >>>> >> >>> >>> >>> conn None rec <sqlalchemy.pool._ConnectionRecord > object at > >>>> >> >>> >>> >>> 0x88fc5d0> > >>>> >> >>> >>> >>> rec.conn None > >>>> >> >>> >>> >>>>>_ConnectionFairy._checkin --> _finalize_fairy(conn, > >>>> >> >>> >>> >>>>> conn_rec, > >>>> >> >>> >>> >>>>> pool, > >>>> >> >>> >>> >>>>> None, > >>>> >> >>> >>> >>>>> echo, fairy) & self.conn = None & self.conn_rec = > None > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.720+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs > >>>> >> >>> >>> >>> _finalize_fairy > >>>> >> >>> >>> >>> args > >>>> >> >>> >>> >>> conn > >>>> >> >>> >>> >>> None, rec.conn None, rec, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord > >>>> >> >>> >>> >>> object at > >>>> >> >>> >>> >>> 0x88fc5d0>. ref None, fairy > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionFairy > >>>> >> >>> >>> >>> object > >>>> >> >>> >>> >>> at > >>>> >> >>> >>> >>> 0x329c0d0> > >>>> >> >>> >>> >>>>>_finalize_fairy --> connection_record.checkin() > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.720+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs going > to > >>>> >> >>> >>> >>> connection_record.checkin > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.721+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs before > conn > >>>> >> >>> >>> >>> checkin > >>>> >> >>> >>> >>> None, > >>>> >> >>> >>> >>> pool queue deque([<sqlalchemy.pool._ConnectionRecord > >>>> >> >>> >>> >>> object at > >>>> >> >>> >>> >>> 0x7524590>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x7a2b990>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0xa856b10>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x7ebee90>]), > >>>> >> >>> >>> >>> finalize_callback > >>>> >> >>> >>> >>> deque([]) > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.721+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs after > conn > >>>> >> >>> >>> >>> checkin, > >>>> >> >>> >>> >>> pool > >>>> >> >>> >>> >>> queue deque([<sqlalchemy.pool._ConnectionRecord object > at > >>>> >> >>> >>> >>> 0x7524590>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x7a2b990>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0xa856b10>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x7ebee90>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x88fc5d0>]) > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.723+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> ERROR > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:122 error] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] Exception > >>>> >> >>> >>> >>> during > >>>> >> >>> >>> >>> reset > >>>> >> >>> >>> >>> or > >>>> >> >>> >>> >>> similar > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.723+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs going > to > >>>> >> >>> >>> >>> connection_record.invalidate > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.724+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs going > to > >>>> >> >>> >>> >>> connection_record.checkin > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.724+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs before > conn > >>>> >> >>> >>> >>> checkin > >>>> >> >>> >>> >>> None, > >>>> >> >>> >>> >>> pool queue deque([<sqlalchemy.pool._ConnectionRecord > >>>> >> >>> >>> >>> object at > >>>> >> >>> >>> >>> 0x7524590>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x7a2b990>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0xa856b10>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x7ebee90>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x88fc5d0>]), > >>>> >> >>> >>> >>> finalize_callback > >>>> >> >>> >>> >>> deque([]) > >>>> >> >>> >>> >>> 2018-05-10T14:02:49.732+08:00 localhost nova-conductor > >>>> >> >>> >>> >>> DEBUG > >>>> >> >>> >>> >>> [pid:4528] > >>>> >> >>> >>> >>> [MainThread] [tid:122769072] [log.py:104 debug] > >>>> >> >>> >>> >>> [req-9e51bb8d-cdfe-434b-859a-9211ac2087f9] jjs after > conn > >>>> >> >>> >>> >>> checkin, > >>>> >> >>> >>> >>> pool > >>>> >> >>> >>> >>> queue deque([<sqlalchemy.pool._ConnectionRecord object > at > >>>> >> >>> >>> >>> 0x7524590>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x7a2b990>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0xa856b10>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x7ebee90>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x88fc5d0>, > >>>> >> >>> >>> >>> <sqlalchemy.pool._ConnectionRecord object at > 0x88fc5d0>]) > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> > >>>> >> >>> >>> >>> 在 2018年5月8日星期二 UTC+8下午11:06:04，[email protected]写道： > >>>> >> >>> >>> >>>> > >>>> >> >>> >>> >>>> I found why we could get the same connection twice > from > >>>> >> >>> >>> >>>> the > >>>> >> >>> >>> >>>> pool... > >>>> >> >>> >>> >>>> > >>>> >> >>> >>> >>>> Because we put it into pool twice. > >>>> >> >>> >>> >>>> > >>>> >> >>> >>> >>>> Any suggestion for finding why it put the same > connection > >>>> >> >>> >>> >>>> into > >>>> >> >>> >>> >>>> pool > >>>> >> >>> >>> >>>> within > >>>> >> >>> >>> >>>> different coroutines? > >>>> >> >>> >>> >>>> > >>>> >> >>> >>> >>>> > >>>> >> >>> >>> >>>> 2018-05-08T22:39:17.448+08:00 localhost > nova-conductor > >>>> >> >>> >>> >>>> DEBUG > >>>> >> >>> >>> >>>> [pid:15755] > >>>> >> >>> >>> >>>> [MainThread] [tid:187954992] [log.py:104 debug] > >>>> >> >>> >>> >>>> [req-7c2199c0-d9a6-4131-8358-2aebcf5a4ce1] jjs conn > >>>> >> >>> >>> >>>> checkin > >>>> >> >>> >>> >>>> <connection > >>>> >> >>> >>> >>>> object at 0x111d9740; closed: 0> > >>>> >> >>> >>> >>>> 2018-05-08T22:39:17.502+08:00 localhost > nova-conductor > >>>> >> >>> >>> >>>> DEBUG > >>>> >> >>> >>> >>>> [pid:15755] > >>>> >> >>> >>> >>>> [MainThread] [tid:178645264] [log.py:104 debug] > >>>> >> >>> >>> >>>> [req-7ab83c30-91bd-4278-b694-85a71035992c] jjs conn > >>>> >> >>> >>> >>>> checkin > >>>> >> >>> >>> >>>> <connection > >>>> >> >>> >>> >>>> object at 0x111d9740; closed: 0> > >>>> >> >>> >>> >>>> ... > >>>> >> >>> >>> >>>> 2018-05-08T22:39:17.992+08:00 localhost > nova-conductor > >>>> >> >>> >>> >>>> DE -- 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.
