The exc_info of tid 130446032 "Exception during reset or similar" is
sqlalchemy.pool.QueuePool Traceback (most recent call last): sqlalchemy.pool.QueuePool File "sqlalchemy/pool.py", line 679, in _finalize_fairy sqlalchemy.pool.QueuePool fairy._reset(pool) sqlalchemy.pool.QueuePool File "sqlalchemy/pool.py", line 825, in _reset sqlalchemy.pool.QueuePool self._reset_agent.rollback() sqlalchemy.pool.QueuePool File "sqlalchemy/engine/base.py", line 1586, in rollback sqlalchemy.pool.QueuePool self._do_rollback() sqlalchemy.pool.QueuePool File "sqlalchemy/engine/base.py", line 1624, in _do_rollback sqlalchemy.pool.QueuePool self.connection._rollback_impl() sqlalchemy.pool.QueuePool File "sqlalchemy/engine/base.py", line 672, in _rollback_impl sqlalchemy.pool.QueuePool self._handle_dbapi_exception(e, None, None, None, None) sqlalchemy.pool.QueuePool File "sqlalchemy/engine/base.py", line 1356, in _handle_dbapi_exception sqlalchemy.pool.QueuePool util.raise_from_cause(newraise, exc_info) sqlalchemy.pool.QueuePool File "sqlalchemy/util/compat.py", line 200, in raise_from_cause sqlalchemy.pool.QueuePool reraise(type(exception), exception, tb=exc_tb) sqlalchemy.pool.QueuePool File "sqlalchemy/engine/base.py", line 670, in _rollback_impl sqlalchemy.pool.QueuePool self.engine.dialect.do_rollback(self.connection) sqlalchemy.pool.QueuePool File "sqlalchemy/engine/default.py", line 421, in do_rollback sqlalchemy.pool.QueuePool dbapi_connection.rollback() sqlalchemy.pool.QueuePool File "eventlet/support/psycopg2_patcher.py", line 46, in eventlet_wait_callback sqlalchemy.pool.QueuePool state = conn.poll() sqlalchemy.pool.QueuePool DBConnectionError: (psycopg2.OperationalError) server closed the connection unexpectedly sqlalchemy.pool.QueuePool This probably means the server terminated abnormally sqlalchemy.pool.QueuePool before or while processing the request. 在 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 <mik...@zzzcomputing.com > <javascript:>> 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, <jiajun...@gmail.com <javascript:>> > 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 <mik...@zzzcomputing.com> > > >>> wrote: > >>> > On Sun, May 13, 2018 at 10:35 PM, <jiajun...@gmail.com> 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 < > mik...@zzzcomputing.com> > >>> >>> 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 > >>> >>> > <mik...@zzzcomputing.com> > >>> >>> > wrote: > >>> >>> >> On Thu, May 10, 2018 at 7:23 AM, <jiajun...@gmail.com> 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，jiajun...@gmail.com写道： > >>> >>> >>>> > >>> >>> >>>> 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，jiajun...@gmail.com写道： > >>> >>> >>>>> > >>> >>> >>>>> 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 <jiajun...@gmail.com> 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 conn > 0x94122f0 > >>> >>> >>>>>>> > >>> >>> >>>>>>> [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] [0xa5db730]conn_poll: poll writing > >>> >>> >>>>>>> > >>> >>> >>>>>>> [49174] [0xa5db730]conn_poll: async_status -> ASYNC_READ > >>> >>> >>>>>>> > >>> >>> >>>>>>> ----- > >>> >>> >>>>>>> > >>> >>> >>>>>>> [49174] [0xa5db4b0]psyco_conn_cursor: new unnamed cursor > for > >>> >>> >>>>>>> connection > >>> >>> >>>>>>> at 0x8de2d30 > >>> >>> >>>>>>> > >>> >>> >>>>>>> [49174] [0xa5db4b0]cursor_setup: init cursor object at > >>> >>> >>>>>>> 0xa6c2650 > >>> >>> >>>>>>> > >>> >>> >>>>>>> [49174] [0xa5db4b0]cursor_setup: parameters: name = > (null), > >>> >>> >>>>>>> conn = > >>> >>> >>>>>>> 0x8de2d30 > >>> >>> >>>>>>> > >>> >>> >>>>>>> [49174] [0xa5db4b0]cursor_setup: good cursor object at > >>> >>> >>>>>>> 0xa6c2650, > >>> >>> >>>>>>> refcnt = 1 > >>> >>> >>>>>>> > >>> >>> >>>>>>> [49174] [0xa5db4b0]psyco_conn_cursor: new cursor at > 0xa6c2650: > >>> >>> >>>>>>> refcnt = > >>> >>> >>>>>>> 1 > >>> >>> >>>>>>> > >>> >>> >>>>>>> [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 > >>> >>> >>>>>>> > >>> >>> >>>>>>> > >>> >>> >>>>>>> 在 2018年4月28日星期六 UTC+8下午4:07:34，jiajun...@gmail.com写道： > >>> >>> >>>>>>>> > >>> >>> >>>>>>>> We reproduced this problem and added logs in psycopg2, > found > >>> >>> >>>>>>>> a > >>> >>> >>>>>>>> confusing thing and reported it to psycopg2. > >>> >>> >>>>>>>> > >>> >>> >>>>>>>> It seems sqlalchemy & psycopg2 stack flow is: > >>> >>> >>>>>>>> 1.from sqlalchemy to psycopg: pq_execute/pq_commit > >>> >>> >>>>>>>> 2.from psycopg to sqlalchemy PyWeakref_NewRef(conn) > >>> >>> >>>>>>>> 3.get exception in sqlalchemy, and do_rollback > >>> >>> >>>>>>>> 4.from sqlalchemy to psycopg: pq_abort > >>> >>> >>>>>>>> 5.psycopg get pthread_mutex_lock deadlock > >>> >>> >>>>>>>> > >>> >>> >>>>>>>> What we have done to reproduce it is: stop master > pg-server > >>> >>> >>>>>>>> and > >>> >>> >>>>>>>> promote the slave pg-server to master, with moving FIP > from > >>> >>> >>>>>>>> old > >>> >>> >>>>>>>> master to > >>> >>> >>>>>>>> slave. At the same time, let nova-conductor do quite a > lot db > >>> >>> >>>>>>>> query > >>> >>> >>>>>>>> requests. > >>> >>> >>>>>>>> > >>> >>> >>>>>>>> [1] https://github.com/psycopg/psycopg2/issues/703 > >>> >>> >>>>>>>> > >>> >>> >>>>>>>> 在 2018年4月23日星期一 UTC+8下午9:45:04，Mike Bayer写道： > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> On Mon, Apr 23, 2018 at 9:03 AM, <jiajun...@gmail.com> > >>> >>> >>>>>>>>> wrote: > >>> >>> >>>>>>>>> > Sorry for reply on this topic. > >>> >>> >>>>>>>>> > > >>> >>> >>>>>>>>> > We recently get the same problem in our production > >>> >>> >>>>>>>>> > environment. > >>> >>> >>>>>>>>> > > >>> >>> >>>>>>>>> > I found a patch in other lib [1], and they added > >>> >>> >>>>>>>>> > conn.close() > >>> >>> >>>>>>>>> > in > >>> >>> >>>>>>>>> > exception > >>> >>> >>>>>>>>> > psycopg2.ProgrammingError. > >>> >>> >>>>>>>>> > > >>> >>> >>>>>>>>> > Shall we do the same in [2] ? > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> SQLAlchemy does things much more carefully than that, we > >>> >>> >>>>>>>>> parse > >>> >>> >>>>>>>>> the > >>> >>> >>>>>>>>> error message for specific ones that correspond to > >>> >>> >>>>>>>>> "connection > >>> >>> >>>>>>>>> is no > >>> >>> >>>>>>>>> longer usable", we call these "is_disconnect" but it can > be > >>> >>> >>>>>>>>> any > >>> >>> >>>>>>>>> invalidating condition. > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> You can make these yourself, and they can also be made > to be > >>> >>> >>>>>>>>> part of > >>> >>> >>>>>>>>> oslo.db, using the handle_error event: > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > http://docs.sqlalchemy.org/en/latest/core/events.html?highlight=handle_error#sqlalchemy.events.ConnectionEvents.handle_error > > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> within oslo.db you would want to propose a change here: > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > https://github.com/openstack/oslo.db/blob/master/oslo_db/sqlalchemy/exc_filters.py#L387 > > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > >>> >>> >>>>>>>>> > > >>> >>> >>>>>>>>> > [1] > >>> >>> >>>>>>>>> > > >>> >>> >>>>>>>>> > > https://github.com/aio-libs/aiopg/pull/415/files?diff=split > >>> >>> >>>>>>>>> > > >>> >>> >>>>>>>>> > [2] > >>> >>> >>>>>>>>> > > >>> >>> >>>>>>>>> > > >>> >>> >>>>>>>>> > > >>> >>> >>>>>>>>> > > https://github.com/zzzeek/sqlalchemy/blob/master/lib/sqlalchemy/engine/base.py#L1289 > > >>> >>> >>>>>>>>> > > >>> >>> >>>>>>>>> > > >>> >>> >>>>>>>>> > 在 2017年11月13日星期一 UTC+8上午10:44:31，JinRong Cai写道： > >>> >>> >>>>>>>>> >> > >>> >>> >>>>>>>>> >> Hi Michael , > >>> >>> >>>>>>>>> >> > >>> >>> >>>>>>>>> >> I am using openstack with postgresql which sqlalchemy > and > >>> >>> >>>>>>>>> >> oslo_db > >>> >>> >>>>>>>>> >> module > >>> >>> >>>>>>>>> >> were used. > >>> >>> >>>>>>>>> >> And there are some problems after my pg database > switched > >>> >>> >>>>>>>>> >> over. > >>> >>> >>>>>>>>> >> > >>> >>> >>>>>>>>> >> Here is my switch over process: > >>> >>> >>>>>>>>> >> 1. nova-conductor(python application) is running with > DB > >>> >>> >>>>>>>>> >> connection > >>> >>> >>>>>>>>> >> strings point to vip , which is in primary site(A) of > pg. > >>> >>> >>>>>>>>> >> 2. switch VIP from primary(A) to new primary(B) > >>> >>> >>>>>>>>> >> 3. switch over pg: shutdown primary(A), promopt > >>> >>> >>>>>>>>> >> standby(B) to > >>> >>> >>>>>>>>> >> new > >>> >>> >>>>>>>>> >> primary. > >>> >>> >>>>>>>>> >> 4. nova-conductor is running in the whole process. > >>> >>> >>>>>>>>> >> > >>> >>> >>>>>>>>> >> After some seconds, I found some nova-conductor > processes > >>> >>> >>>>>>>>> >> are > >>> >>> >>>>>>>>> >> hang > >>> >>> >>>>>>>>> >> with > >>> >>> >>>>>>>>> >> status futex_wait_queue_me, and the status of the > query > >>> >>> >>>>>>>>> >> in DB > >>> >>> >>>>>>>>> >> is > >>> >>> >>>>>>>>> >> "idle in > >>> >>> >>>>>>>>> >> transaction", the transaction was not commited or > >>> >>> >>>>>>>>> >> rollbacked! > >>> >>> >>>>>>>>> >> I think disconnection was handled in the oslo_db, > which > >>> >>> >>>>>>>>> >> will > >>> >>> >>>>>>>>> >> send > >>> >>> >>>>>>>>> >> a > >>> >>> >>>>>>>>> >> ping(select 1) to DB. > >>> >>> >>>>>>>>> >> > >>> >>> >>>>>>>>> >> If DB was switchd over, the connection in the pool > would > >>> >>> >>>>>>>>> >> be > >>> >>> >>>>>>>>> >> set > >>> >>> >>>>>>>>> >> with > >>> >>> >>>>>>>>> >> status invalid, and reconnect after next check out. > >>> >>> >>>>>>>>> >> > >>> >>> >>>>>>>>> >> ###error messages from nova-conductor > >>> >>> >>>>>>>>> >> localhost nova-conductor ERROR [pid:36365] > [MainThread] > >>> >>> >>>>>>>>> >> [tid:122397712] > > -- SQLAlchemy - The Python SQL Toolkit and Object Relational Mapper http://www.sqlalchemy.org/ To post example code, please provide an MCVE: Minimal, Complete, and Verifiable Example. See http://stackoverflow.com/help/mcve for a full description. --- You received this message because you are subscribed to the Google Groups "sqlalchemy" group. To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy+unsubscr...@googlegroups.com. To post to this group, send email to sqlalchemy@googlegroups.com. Visit this group at https://groups.google.com/group/sqlalchemy. For more options, visit https://groups.google.com/d/optout.
