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.
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] <javascript:>> > 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 > DEBUG > >> >>> >>> >>>> [pid:15755] > >> >>> >>> >>>> [MainThread] [tid:309091856] [log.py:104 debug] > >> >>> >>> >>>> [req-dee5dd2d-866f-408e-999b-b415ea7ce953] Connection > >> >>> >>> >>>> <connection > >> >>> >>> >>>> object at > >> >>> >>> >>>> 0x111d9740; closed: 0> checked out from pool > >> >>> >>> >>>> 2018-05-08T22:39:18.039+08:00 localhost nova-conductor > DEBUG > >> >>> >>> >>>> [pid:15755] > >> >>> >>> >>>> [MainThread] [tid:178645104] [log.py:104 debug] > >> >>> >>> >>>> [req-ac8017d7-c97e-44ca-92d2-99f180858e14] Connection > >> >>> >>> >>>> <connection > >> >>> >>> >>>> object at > >> >>> >>> >>>> 0x111d9740; closed: 0> checked out from pool > >> >>> >>> >>>> > >> >>> >>> >>>> > >> >>> >>> >>>> 在 2018年5月8日星期二 UTC+8下午10:18:52，[email protected]写道： > >> >>> >>> >>>>> > >> >>> >>> >>>>> I added logs in sqlalchemy/pool.py > >> >>> >>> >>>>> > >> >>> >>> >>>>> QueuePool.checkout > >> >>> >>> >>>>> > >> >>> >>> >>>>> @classmethod > >> >>> >>> >>>>> def checkout(cls, pool): > >> >>> >>> >>>>> rec = pool._do_get() > >> >>> >>> >>>>> try: > >> >>> >>> >>>>> dbapi_connection = rec.get_connection() > >> >>> >>> >>>>> pool.logger.debug("jjs get conn success %s", > >> >>> >>> >>>>> dbapi_connection) > >> >>> >>> >>>>> except: > >> >>> >>> >>>>> pool.logger.debug("jjs get error in > get_connection") > >> >>> >>> >>>>> with util.safe_reraise(): > >> >>> >>> >>>>> rec.checkin() > >> >>> >>> >>>>> echo = pool._should_log_debug() > >> >>> >>> >>>>> fairy = _ConnectionFairy(dbapi_connection, rec, echo) > >> >>> >>> >>>>> rec.fairy_ref = weakref.ref( > >> >>> >>> >>>>> fairy, > >> >>> >>> >>>>> lambda ref: _finalize_fairy and > >> >>> >>> >>>>> _finalize_fairy( > >> >>> >>> >>>>> dbapi_connection, > >> >>> >>> >>>>> rec, pool, ref, echo) > >> >>> >>> >>>>> ) > >> >>> >>> >>>>> _refs.add(rec) > >> >>> >>> >>>>> if echo: > >> >>> >>> >>>>> pool.logger.debug("jjs conn %s, pool status %s", > >> >>> >>> >>>>> dbapi_connection, pool.status()) > >> >>> >>> >>>>> pool.logger.debug("Connection %r checked out from > >> >>> >>> >>>>> pool", > >> >>> >>> >>>>> dbapi_connection) > >> >>> >>> >>>>> return fairy > >> >>> >>> >>>>> > >> >>> >>> >>>>> Then I got logs below: > >> >>> >>> >>>>> > >> >>> >>> >>>>> coroutine A: > >> >>> >>> >>>>> > >> >>> >>> >>>>> 2018-05-08T21:39:59.055+08:00 localhost nova-conductor > INFO > >> >>> >>> >>>>> [pid:55528] > >> >>> >>> >>>>> [MainThread] [tid:197123760] [log.py:109 info] > >> >>> >>> >>>>> [req-ba1ab897-c80a-4bc4-922a-39044d669da1] jjs Pool wait > is > >> >>> >>> >>>>> False, > >> >>> >>> >>>>> timeout > >> >>> >>> >>>>> 30 > >> >>> >>> >>>>> 2018-05-08T21:39:59.078+08:00 localhost nova-conductor > DEBUG > >> >>> >>> >>>>> [pid:55528] > >> >>> >>> >>>>> [MainThread] [tid:197123760] [log.py:104 debug] > >> >>> >>> >>>>> [req-ba1ab897-c80a-4bc4-922a-39044d669da1] Created new > >> >>> >>> >>>>> connection > >> >>> >>> >>>>> <connection object at 0x903f8c0; closed: 0> > >> >>> >>> >>>>> 2018-05-08T21:39:59.079+08:00 localhost nova-conductor > DEBUG > >> >>> >>> >>>>> [pid:55528] > >> >>> >>> >>>>> [MainThread] [tid:197123760] [log.py:104 debug] > >> >>> >>> >>>>> [req-ba1ab897-c80a-4bc4-922a-39044d669da1] jjs get conn > >> >>> >>> >>>>> success > >> >>> >>> >>>>> <connection > >> >>> >>> >>>>> object at 0x903f8c0; closed: 0> > >> >>> >>> >>>>> 2018-05-08T21:39:59.080+08:00 localhost nova-conductor > DEBUG > >> >>> >>> >>>>> [pid:55528] > >> >>> >>> >>>>> [MainThread] [tid:197123760] [log.py:104 debug] > >> >>> >>> >>>>> [req-ba1ab897-c80a-4bc4-922a-39044d669da1] jjs conn > >> >>> >>> >>>>> <connection > >> >>> >>> >>>>> object at > >> >>> >>> >>>>> 0x903f8c0; closed: 0>, pool status Pool size: 10 > >> >>> >>> >>>>> Connections > >> >>> >>> >>>>> in > >> >>> >>> >>>>> pool: 1 > >> >>> >>> >>>>> Current Overflow: 36 Max Overflow: 40 Current Checked out > >> >>> >>> >>>>> connections: 45 > >> >>> >>> >>>>> 2018-05-08T21:39:59.080+08:00 localhost nova-conductor > DEBUG > >> >>> >>> >>>>> [pid:55528] > >> >>> >>> >>>>> [MainThread] [tid:197123760] [log.py:104 debug] > >> >>> >>> >>>>> [req-ba1ab897-c80a-4bc4-922a-39044d669da1] Connection > >> >>> >>> >>>>> <connection > >> >>> >>> >>>>> object at > >> >>> >>> >>>>> 0x903f8c0; closed: 0> checked out from pool > >> >>> >>> >>>>> > >> >>> >>> >>>>> coroutine B: > >> >>> >>> >>>>> > >> >>> >>> >>>>> 2018-05-08T21:39:59.212+08:00 localhost nova-conductor > INFO > >> >>> >>> >>>>> [pid:55528] > >> >>> >>> >>>>> [MainThread] [tid:151519312] [log.py:109 info] > >> >>> >>> >>>>> [req-a78075b5-c55c-40c4-86d0-65957e89cb56] jjs Pool wait > is > >> >>> >>> >>>>> False, > >> >>> >>> >>>>> timeout > >> >>> >>> >>>>> 30 > >> >>> >>> >>>>> 2018-05-08T21:39:59.213+08:00 localhost nova-conductor > DEBUG > >> >>> >>> >>>>> [pid:55528] > >> >>> >>> >>>>> [MainThread] [tid:151519312] [log.py:104 debug] > >> >>> >>> >>>>> [req-a78075b5-c55c-40c4-86d0-65957e89cb56] jjs get conn > >> >>> >>> >>>>> success > >> >>> >>> >>>>> <connection > >> >>> >>> >>>>> object at 0x903f8c0; closed: 0> > >> >>> >>> >>>>> 2018-05-08T21:39:59.213+08:00 localhost nova-conductor > DEBUG > >> >>> >>> >>>>> [pid:55528] > >> >>> >>> >>>>> [MainThread] [tid:151519312] [log.py:104 debug] > >> >>> >>> >>>>> [req-a78075b5-c55c-40c4-86d0-65957e89cb56] jjs conn > >> >>> >>> >>>>> <connection > >> >>> >>> >>>>> object at > >> >>> >>> >>>>> 0x903f8c0; closed: 0>, pool status Pool size: 10 > >> >>> >>> >>>>> Connections in > >> >>> >>> >>>>> pool: 0 > >> >>> >>> >>>>> Current Overflow: 36 Max Overflow: 40 Current Checked out > >> >>> >>> >>>>> connections: 46 > >> >>> >>> >>>>> 2018-05-08T21:39:59.214+08:00 localhost nova-conductor > DEBUG > >> >>> >>> >>>>> [pid:55528] > >> >>> >>> >>>>> [MainThread] [tid:151519312] [log.py:104 debug] > >> >>> >>> >>>>> [req-a78075b5-c55c-40c4-86d0-65957e89cb56] Connection > >> >>> >>> >>>>> <connection > >> >>> >>> >>>>> object at > >> >>> >>> >>>>> 0x903f8c0; closed: 0> checked out from pool > >> >>> >>> >>>>> > >> >>> >>> >>>>> > >> >>> >>> >>>>> It seems that when we create_connection in > >> >>> >>> >>>>> QueuePool._do_get, we > >> >>> >>> >>>>> may > >> >>> >>> >>>>> not > >> >>> >>> >>>>> get the lock _pool.mutex(~Queue.mutex). > >> >>> >>> >>>>> > >> >>> >>> >>>>> > >> >>> >>> >>>>> > >> >>> >>> >>>>> 在 2018年5月7日星期一 UTC+8下午8:41:14，Mike Bayer写道： > >> >>> >>> >>>>>> > >> >>> >>> >>>>>> > >> >>> >>> >>>>>> > >> >>> >>> >>>>>> On Mon, May 7, 2018, 7:01 AM <[email protected]> > wrote: > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> We added coroutine_id in psycopg2, and found that two > >> >>> >>> >>>>>>> coroutine > >> >>> >>> >>>>>>> use the > >> >>> >>> >>>>>>> same connection before the pthread_mutex_lock released. > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> Maybe something in the connection pool goes wrong? > >> >>> >>> >>>>>>> [pid] [coroutine_id] msg > >> >>> >>> >>>>>> > >> >>> >>> >>>>>> > >> >>> >>> >>>>>> > >> >>> >>> >>>>>> This seems unlikely. Openstack uses the SQLAlchemy > >> >>> >>> >>>>>> connection > >> >>> >>> >>>>>> pool > >> >>> >>> >>>>>> with eventlet patching in conjunction with the MySQL > >> >>> >>> >>>>>> drivers > >> >>> >>> >>>>>> and > >> >>> >>> >>>>>> nothing > >> >>> >>> >>>>>> like that happens. The biggest issue SQLAlchemy had > with > >> >>> >>> >>>>>> greenlets is that > >> >>> >>> >>>>>> a timed out greenlet would throw GreenletExit and cause > a > >> >>> >>> >>>>>> dirty > >> >>> >>> >>>>>> connection > >> >>> >>> >>>>>> to go back into the pool, that was fixed in 1.2. > >> >>> >>> >>>>>> > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> [49174] [0xa5db730]before PyObject_CallFunctionObjArgs > >> >>> >>> >>>>>>> conn > >> >>> >>> >>>>>>> 0x94122f0, > >> >>> >>> >>>>>>> cb 0x23ad320 > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> [49174] [0xa5db730]conn_poll: status = 2, conn > 0x94122f0 > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> [49174] [0xa5db730]conn_poll: async_status = > ASYNC_WRITE > >> >>> >>> >>>>>>> 0x94122f0 > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> [49174] [0xa5db4b0]before EXC_IF_ASYNC_IN_PROGRESS conn > >> >>> >>> >>>>>>> 0x94122f0, > >> >>> >>> >>>>>>> async_cursor 0x881ac00 > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> [49174] [0xa5db4b0]before EXC_IF_ASYNC_IN_PROGRESS conn > >> >>> >>> >>>>>>> 0x94122f0, > >> >>> >>> >>>>>>> async_cursor 0x881ac00 > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> [49174] [0xa5db4b0]pq_abort: enter pgconn = 0x94122f0, > >> >>> >>> >>>>>>> autocommit > >> >>> >>> >>>>>>> = 0, > >> >>> >>> >>>>>>> status = 2 > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> [49174] [0xa5db4b0]before lock pgconn = 0x94122f0, > owner > >> >>> >>> >>>>>>> 49174 > >> >>> >>> >>>>>>> __lock 1 > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> Below is the logs grep by coroutine id: > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> [49174] [0xa5db730]finish send query, before > psyco_wait, > >> >>> >>> >>>>>>> conn > >> >>> >>> >>>>>>> 0x94122f0 > >> >>> >>> >>>>>>> > >> >>> >>> >>>>>>> [49174] [0xa5db730]before have_wait_callback con -- 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.
