SQLAlchemy lock-up when logging to a database
415 views
Skip to first unread message
Stefan Schwarzer
Feb 21, 2018, 7:16:42 AM2/21/18
to sqlalchemy
In our project we recently ran into the problem that SQLAlchemy would
block when creating a connection for logging to a database.
Set-up:
Oracle server 11.2
cx_Oracle 6.1
SQLAlchemy 1.2.3
The example code for `connection_lockup.py` is:
======================================================================
"""
Example script to demonstrate a lock-up when trying to create a second
connection _while_ creating a first connection.
Do _not_ modify the program to create the table and attempt to block
in the same run. In this case, the lockup won't happen. Instead run
the program first with `connection_lockup.py make_table` (unless the
table already exists), then with `connection_lockup.py block`.
"""
import datetime
import logging
import os
import sys
import threading
import sqlalchemy
# Set connect string (starting with `oracle+cx_oracle://`) in environment.
# I don't know if the problem also occurs with other dialects.
CONNECT_STRING = os.getenv("CONNECT_STRING")
# Schema and engine set-up.
metadata = sqlalchemy.MetaData()
log_table = sqlalchemy.Table(
"log2", metadata,
sqlalchemy.Column("id", sqlalchemy.Integer,
sqlalchemy.schema.Sequence("log_id_seq"),
primary_key=True),
sqlalchemy.Column("timestamp_utc",
sqlalchemy.TIMESTAMP(timezone=False),
nullable=False),
sqlalchemy.Column("level_name", sqlalchemy.Unicode(1000)),
sqlalchemy.Column("message", sqlalchemy.Unicode(1000),
nullable=False))
engine = sqlalchemy.create_engine(CONNECT_STRING)
# ----------------------------------------------------------------------
def make_table():
log_table.create(engine, checkfirst=True)
class DatabaseHandler(logging.Handler):
"""
Handler for logging to Oracle database
"""
def __init__(self, *args, **kwargs):
super().__init__(*args, **kwargs)
# Keep a reference to the engine for the log database.
self._engine = engine
# Make sure that at least one connection has been retrieved from the
# engine before database logging is set up.
# with self._engine.connect() as _connection:
# pass
# For preventing that the logging `INSERT` statement is also logged.
thread_local = threading.local()
thread_local.emit_lock = threading.Lock()
self._emit_lock = thread_local.emit_lock
def _emit(self, record):
"""
Emit the log record.
"""
# Some code causes a log message being an empty string. This wouldn't be
# a problem, but Oracle implicitly converts this to `NULL`, which in
# turn causes an `IntegrityError` when the log record is about to be
# written to the database. Therefore, in this case set the message to a
# sensible (non-empty) string.
message = record.msg
if not message:
message = "(no log message)"
else:
message = message % record.args
insert = log_table.insert()
insert = insert.values(
# According to the documentation
# https://docs.python.org/3/library/logging.html#logrecord-attributes
# the `created` attribute is filled from `time.time()`, which
# uses local time. Therefore, use `utcfromtimestamp` to get
# an UTC timestamp.
timestamp_utc=datetime.datetime.utcfromtimestamp(record.created),
level_name=record.levelname,
message=message)
# Run `INSERT` in a transaction. See
# http://docs.sqlalchemy.org/en/latest/core/connections.html#using-transactions
with self._engine.begin() as connection:
connection.execute(insert)
def emit(self, record):
"""
Emit the log record.
Make sure that emitting the log record isn't invoked recursively, i. e.
when SQLAlchemy itself would log something while inserting the log
record into the database.
"""
is_acquired = self._emit_lock.acquire(blocking=False)
if not is_acquired:
# An "outer" call of `emit` acquired the lock before. Since we don't
# want any recursive calls, return immediately.
return
# Don't use a `with` statement here because this would try to acquire
# the lock. See
# https://docs.python.org/3/library/threading.html#using-locks-conditions-and-semaphores-in-the-with-statement
try:
self._emit(record)
finally:
self._emit_lock.release()
def block():
logger = logging.getLogger("sqlalchemy")
logger.addHandler(DatabaseHandler())
logger.setLevel(logging.INFO)
# Blocks.
#
# For this to "work", this must be the first connection created for the
# engine.
connection = engine.connect()
def main(command):
if command == "make_table":
make_table()
elif command == "block":
block()
else:
print("invalid command {!r}".format(command))
if __name__ == "__main__":
if len(sys.argv) != 2:
print("usage: connection_lockup.py make_table|block")
sys.exit()
command = sys.argv[1]
main(command)
======================================================================
You need to run the program at least twice.
Once to create the log table, with
$ export CONNECT_STRING='oracle+cx_oracle://...'
$ python connection_lockup.py make_table
then with
$ python connection_lockup.py block
to see SQLAlchemy block.
When pressing ctrl-c, the result is the following traceback
(interspersed with some comments).
======================================================================
$ python connection_lockup.py block
^CTraceback (most recent call last):
File "connection_lockup.py", line 142, in <module>
main(command)
File "connection_lockup.py", line 132, in main
block()
File "connection_lockup.py", line 125, in block
connection = engine.connect()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2102, in connect
return self._connection_cls(self, **kwargs)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 90, in __init__
if connection is not None else engine.raw_connection()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2188, in raw_connection
self.pool.unique_connection, _connection)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2158, in _wrap_pool_connect
return fn()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 345, in unique_connection
return _ConnectionFairy._checkout(self)
[This section repeats further down for the connection attempt in the
database log handler.]
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 784, in _checkout
fairy = _ConnectionRecord.checkout(pool)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 532, in checkout
rec = pool._do_get()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 1189, in _do_get
self._dec_overflow()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 66, in __exit__
compat.reraise(exc_type, exc_value, exc_tb)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 187, in reraise
raise value
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 1186, in _do_get
return self._create_connection()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 350, in _create_connection
return _ConnectionRecord(self)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 477, in __init__
self.__connect(first_connect_check=True)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 677, in __connect
exec_once(self.connection, self)
[End of repeating section]
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/event/attr.py", line 271, in exec_once
self(*args, **kw)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/event/attr.py", line 281, in __call__
fn(*args, **kw)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 1334, in go
return once_fn(*arg, **kw)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/strategies.py", line 183, in first_connect
dialect.initialize(c)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/dialects/oracle/cx_oracle.py", line 663, in initialize
super(OracleDialect_cx_oracle, self).initialize(connection)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/dialects/oracle/base.py", line 1091, in initialize
super(OracleDialect, self).initialize(connection)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 267, in initialize
self._get_default_schema_name(connection)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/dialects/oracle/base.py", line 1179, in _get_default_schema_name
connection.execute('SELECT USER FROM DUAL').scalar())
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 942, in execute
return self._execute_text(object, multiparams, params)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1104, in _execute_text
statement, parameters
[Log call from SQLAlchemy]
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1151, in _execute_context
self.engine.logger.info(statement)
[In `logging`]
File "/usr/lib/python3.6/logging/__init__.py", line 1306, in info
self._log(INFO, msg, args, **kwargs)
File "/usr/lib/python3.6/logging/__init__.py", line 1442, in _log
self.handle(record)
File "/usr/lib/python3.6/logging/__init__.py", line 1452, in handle
self.callHandlers(record)
File "/usr/lib/python3.6/logging/__init__.py", line 1514, in callHandlers
hdlr.handle(record)
File "/usr/lib/python3.6/logging/__init__.py", line 863, in handle
self.emit(record)
[In the database log handler]
File "connection_lockup.py", line 112, in emit
self._emit(record)
File "connection_lockup.py", line 92, in _emit
with self._engine.begin() as connection:
[Connection attempt in the database log handler]
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1992, in begin
conn = self.contextual_connect(close_with_result=close_with_result)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2123, in contextual_connect
self._wrap_pool_connect(self.pool.connect, None),
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2158, in _wrap_pool_connect
return fn()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 403, in connect
return _ConnectionFairy._checkout(self)
[Repeating section of traceback, see above]
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 784, in _checkout
fairy = _ConnectionRecord.checkout(pool)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 532, in checkout
rec = pool._do_get()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 1189, in _do_get
self._dec_overflow()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 66, in __exit__
compat.reraise(exc_type, exc_value, exc_tb)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 187, in reraise
raise value
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 1186, in _do_get
return self._create_connection()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 350, in _create_connection
return _ConnectionRecord(self)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 477, in __init__
self.__connect(first_connect_check=True)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 677, in __connect
exec_once(self.connection, self)
[SQLAlchemy blocks here, waiting for the lock. This seems to be the
only place in the SQLAlchemy code where this lock is used.]
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/event/attr.py", line 268, in exec_once
with self._exec_once_mutex:
KeyboardInterrupt
======================================================================
It's worth noting that this blocking only happens if no other
connection has been created for the engine before (which also implies
that nothing was logged to the database when `engine.connect` is
called for the first time).
Our current workaround is to make sure that at least one connection is
created before the first log call happens. The above code does this in
`DatabaseHandler.__init__` (commented out). If you uncomment the
`with` block there, no blocking happens.
Do you have any advice? Should we stick with the workaround? Is there
anything else we should do?
Do you consider this problem a bug in SQLAlchemy? Admittedly it's an
edge case. At the moment, I can't think of any situation that would
try a first connection of an engine from the same thread recursively.
On the other hand, I think that logging to the database as above is a
legitimate use case.
What do you think?
Best regards,
Stefan
block when creating a connection for logging to a database.
Set-up:
Oracle server 11.2
cx_Oracle 6.1
SQLAlchemy 1.2.3
The example code for `connection_lockup.py` is:
======================================================================
"""
Example script to demonstrate a lock-up when trying to create a second
connection _while_ creating a first connection.
Do _not_ modify the program to create the table and attempt to block
in the same run. In this case, the lockup won't happen. Instead run
the program first with `connection_lockup.py make_table` (unless the
table already exists), then with `connection_lockup.py block`.
"""
import datetime
import logging
import os
import sys
import threading
import sqlalchemy
# Set connect string (starting with `oracle+cx_oracle://`) in environment.
# I don't know if the problem also occurs with other dialects.
CONNECT_STRING = os.getenv("CONNECT_STRING")
# Schema and engine set-up.
metadata = sqlalchemy.MetaData()
log_table = sqlalchemy.Table(
"log2", metadata,
sqlalchemy.Column("id", sqlalchemy.Integer,
sqlalchemy.schema.Sequence("log_id_seq"),
primary_key=True),
sqlalchemy.Column("timestamp_utc",
sqlalchemy.TIMESTAMP(timezone=False),
nullable=False),
sqlalchemy.Column("level_name", sqlalchemy.Unicode(1000)),
sqlalchemy.Column("message", sqlalchemy.Unicode(1000),
nullable=False))
engine = sqlalchemy.create_engine(CONNECT_STRING)
# ----------------------------------------------------------------------
def make_table():
log_table.create(engine, checkfirst=True)
class DatabaseHandler(logging.Handler):
"""
Handler for logging to Oracle database
"""
def __init__(self, *args, **kwargs):
super().__init__(*args, **kwargs)
# Keep a reference to the engine for the log database.
self._engine = engine
# Make sure that at least one connection has been retrieved from the
# engine before database logging is set up.
# with self._engine.connect() as _connection:
# pass
# For preventing that the logging `INSERT` statement is also logged.
thread_local = threading.local()
thread_local.emit_lock = threading.Lock()
self._emit_lock = thread_local.emit_lock
def _emit(self, record):
"""
Emit the log record.
"""
# Some code causes a log message being an empty string. This wouldn't be
# a problem, but Oracle implicitly converts this to `NULL`, which in
# turn causes an `IntegrityError` when the log record is about to be
# written to the database. Therefore, in this case set the message to a
# sensible (non-empty) string.
message = record.msg
if not message:
message = "(no log message)"
else:
message = message % record.args
insert = log_table.insert()
insert = insert.values(
# According to the documentation
# https://docs.python.org/3/library/logging.html#logrecord-attributes
# the `created` attribute is filled from `time.time()`, which
# uses local time. Therefore, use `utcfromtimestamp` to get
# an UTC timestamp.
timestamp_utc=datetime.datetime.utcfromtimestamp(record.created),
level_name=record.levelname,
message=message)
# Run `INSERT` in a transaction. See
# http://docs.sqlalchemy.org/en/latest/core/connections.html#using-transactions
with self._engine.begin() as connection:
connection.execute(insert)
def emit(self, record):
"""
Emit the log record.
Make sure that emitting the log record isn't invoked recursively, i. e.
when SQLAlchemy itself would log something while inserting the log
record into the database.
"""
is_acquired = self._emit_lock.acquire(blocking=False)
if not is_acquired:
# An "outer" call of `emit` acquired the lock before. Since we don't
# want any recursive calls, return immediately.
return
# Don't use a `with` statement here because this would try to acquire
# the lock. See
# https://docs.python.org/3/library/threading.html#using-locks-conditions-and-semaphores-in-the-with-statement
try:
self._emit(record)
finally:
self._emit_lock.release()
def block():
logger = logging.getLogger("sqlalchemy")
logger.addHandler(DatabaseHandler())
logger.setLevel(logging.INFO)
# Blocks.
#
# For this to "work", this must be the first connection created for the
# engine.
connection = engine.connect()
def main(command):
if command == "make_table":
make_table()
elif command == "block":
block()
else:
print("invalid command {!r}".format(command))
if __name__ == "__main__":
if len(sys.argv) != 2:
print("usage: connection_lockup.py make_table|block")
sys.exit()
command = sys.argv[1]
main(command)
======================================================================
You need to run the program at least twice.
Once to create the log table, with
$ export CONNECT_STRING='oracle+cx_oracle://...'
$ python connection_lockup.py make_table
then with
$ python connection_lockup.py block
to see SQLAlchemy block.
When pressing ctrl-c, the result is the following traceback
(interspersed with some comments).
======================================================================
$ python connection_lockup.py block
^CTraceback (most recent call last):
File "connection_lockup.py", line 142, in <module>
main(command)
File "connection_lockup.py", line 132, in main
block()
File "connection_lockup.py", line 125, in block
connection = engine.connect()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2102, in connect
return self._connection_cls(self, **kwargs)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 90, in __init__
if connection is not None else engine.raw_connection()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2188, in raw_connection
self.pool.unique_connection, _connection)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2158, in _wrap_pool_connect
return fn()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 345, in unique_connection
return _ConnectionFairy._checkout(self)
[This section repeats further down for the connection attempt in the
database log handler.]
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 784, in _checkout
fairy = _ConnectionRecord.checkout(pool)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 532, in checkout
rec = pool._do_get()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 1189, in _do_get
self._dec_overflow()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 66, in __exit__
compat.reraise(exc_type, exc_value, exc_tb)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 187, in reraise
raise value
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 1186, in _do_get
return self._create_connection()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 350, in _create_connection
return _ConnectionRecord(self)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 477, in __init__
self.__connect(first_connect_check=True)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 677, in __connect
exec_once(self.connection, self)
[End of repeating section]
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/event/attr.py", line 271, in exec_once
self(*args, **kw)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/event/attr.py", line 281, in __call__
fn(*args, **kw)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 1334, in go
return once_fn(*arg, **kw)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/strategies.py", line 183, in first_connect
dialect.initialize(c)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/dialects/oracle/cx_oracle.py", line 663, in initialize
super(OracleDialect_cx_oracle, self).initialize(connection)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/dialects/oracle/base.py", line 1091, in initialize
super(OracleDialect, self).initialize(connection)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/default.py", line 267, in initialize
self._get_default_schema_name(connection)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/dialects/oracle/base.py", line 1179, in _get_default_schema_name
connection.execute('SELECT USER FROM DUAL').scalar())
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 942, in execute
return self._execute_text(object, multiparams, params)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1104, in _execute_text
statement, parameters
[Log call from SQLAlchemy]
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1151, in _execute_context
self.engine.logger.info(statement)
[In `logging`]
File "/usr/lib/python3.6/logging/__init__.py", line 1306, in info
self._log(INFO, msg, args, **kwargs)
File "/usr/lib/python3.6/logging/__init__.py", line 1442, in _log
self.handle(record)
File "/usr/lib/python3.6/logging/__init__.py", line 1452, in handle
self.callHandlers(record)
File "/usr/lib/python3.6/logging/__init__.py", line 1514, in callHandlers
hdlr.handle(record)
File "/usr/lib/python3.6/logging/__init__.py", line 863, in handle
self.emit(record)
[In the database log handler]
File "connection_lockup.py", line 112, in emit
self._emit(record)
File "connection_lockup.py", line 92, in _emit
with self._engine.begin() as connection:
[Connection attempt in the database log handler]
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 1992, in begin
conn = self.contextual_connect(close_with_result=close_with_result)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2123, in contextual_connect
self._wrap_pool_connect(self.pool.connect, None),
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/engine/base.py", line 2158, in _wrap_pool_connect
return fn()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 403, in connect
return _ConnectionFairy._checkout(self)
[Repeating section of traceback, see above]
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 784, in _checkout
fairy = _ConnectionRecord.checkout(pool)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 532, in checkout
rec = pool._do_get()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 1189, in _do_get
self._dec_overflow()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/util/langhelpers.py", line 66, in __exit__
compat.reraise(exc_type, exc_value, exc_tb)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/util/compat.py", line 187, in reraise
raise value
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 1186, in _do_get
return self._create_connection()
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 350, in _create_connection
return _ConnectionRecord(self)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 477, in __init__
self.__connect(first_connect_check=True)
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/pool.py", line 677, in __connect
exec_once(self.connection, self)
[SQLAlchemy blocks here, waiting for the lock. This seems to be the
only place in the SQLAlchemy code where this lock is used.]
File "/home/.virtualenvs/connection_lockup/lib/python3.6/site-packages/sqlalchemy/event/attr.py", line 268, in exec_once
with self._exec_once_mutex:
KeyboardInterrupt
======================================================================
It's worth noting that this blocking only happens if no other
connection has been created for the engine before (which also implies
that nothing was logged to the database when `engine.connect` is
called for the first time).
Our current workaround is to make sure that at least one connection is
created before the first log call happens. The above code does this in
`DatabaseHandler.__init__` (commented out). If you uncomment the
`with` block there, no blocking happens.
Do you have any advice? Should we stick with the workaround? Is there
anything else we should do?
Do you consider this problem a bug in SQLAlchemy? Admittedly it's an
edge case. At the moment, I can't think of any situation that would
try a first connection of an engine from the same thread recursively.
On the other hand, I think that logging to the database as above is a
legitimate use case.
What do you think?
Best regards,
Stefan
Mike Bayer
Feb 21, 2018, 12:44:33 PM2/21/18
to sqlal...@googlegroups.com
On Wed, Feb 21, 2018 at 7:16 AM, Stefan Schwarzer
<sschw...@sschwarzer.net> wrote:
> In our project we recently ran into the problem that SQLAlchemy would
> block when creating a connection for logging to a database.
>
>
<sschw...@sschwarzer.net> wrote:
> In our project we recently ran into the problem that SQLAlchemy would
> block when creating a connection for logging to a database.
>
>
> It's worth noting that this blocking only happens if no other
> connection has been created for the engine before (which also implies
> that nothing was logged to the database when `engine.connect` is
> called for the first time).
>
> Our current workaround is to make sure that at least one connection is
> created before the first log call happens. The above code does this in
> `DatabaseHandler.__init__` (commented out). If you uncomment the
> `with` block there, no blocking happens.
>
> Do you have any advice? Should we stick with the workaround? Is there
> anything else we should do?
>
> Do you consider this problem a bug in SQLAlchemy? Admittedly it's an
> edge case. At the moment, I can't think of any situation that would
> try a first connection of an engine from the same thread recursively.
> On the other hand, I think that logging to the database as above is a
> legitimate use case.
I can come up with other things that can break based on the idea that
> connection has been created for the engine before (which also implies
> that nothing was logged to the database when `engine.connect` is
> called for the first time).
>
> Our current workaround is to make sure that at least one connection is
> created before the first log call happens. The above code does this in
> `DatabaseHandler.__init__` (commented out). If you uncomment the
> `with` block there, no blocking happens.
>
> Do you have any advice? Should we stick with the workaround? Is there
> anything else we should do?
>
> Do you consider this problem a bug in SQLAlchemy? Admittedly it's an
> edge case. At the moment, I can't think of any situation that would
> try a first connection of an engine from the same thread recursively.
> On the other hand, I think that logging to the database as above is a
> legitimate use case.
you're doing a full connection + execute sequence within the log
handler deep within that engine's own processes, such as, it can cause
connection pool exhaustion when you're working with the last
connection available, then your logger has no connection, it goes to
get one and...hang. I can reproduce this with your script (set
pool_size=1, max_overflow=0, set up logging and run an execute() so it
actually logs, and it hangs for 30 seconds until the timeout and
crashes, see stack trace below), so your approach is not safe in any
case.
It would be a lot simpler and robust if your log handler just used its
own Engine (make a new one from the engine.url you already have).
That way you can lose all that re-entrant mutex stuff too.
Traceback (most recent call last):
main(command)
File "test.py", line 124, in main
block()
File "test.py", line 117, in block
connection.execute("select 1")
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py",
line 942, in execute
return self._execute_text(object, multiparams, params)
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py",
return self._execute_text(object, multiparams, params)
line 1104, in _execute_text
statement, parameters
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py",
statement, parameters
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/log.py", line 109, in info
self.log(logging.INFO, msg, *args, **kwargs)
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/log.py", line 155, in log
self.logger._log(level, msg, args, **kwargs)
File "/usr/lib64/python3.6/logging/__init__.py", line 1442, in _log
self.handle(record)
File "/usr/lib64/python3.6/logging/__init__.py", line 1452, in handle
self.callHandlers(record)
File "/usr/lib64/python3.6/logging/__init__.py", line 1514, in callHandlers
hdlr.handle(record)
File "/usr/lib64/python3.6/logging/__init__.py", line 863, in handle
self.emit(record)
File "test.py", line 102, in emit
self._emit(record)
File "test.py", line 82, in _emit
with self._engine.begin() as connection:
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py",
line 1992, in begin
conn = self.contextual_connect(close_with_result=close_with_result)
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py",
conn = self.contextual_connect(close_with_result=close_with_result)
line 2123, in contextual_connect
self._wrap_pool_connect(self.pool.connect, None),
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py",
self._wrap_pool_connect(self.pool.connect, None),
line 2158, in _wrap_pool_connect
return fn()
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/pool.py", line
return fn()
403, in connect
return _ConnectionFairy._checkout(self)
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/pool.py", line
return _ConnectionFairy._checkout(self)
784, in _checkout
fairy = _ConnectionRecord.checkout(pool)
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/pool.py", line
fairy = _ConnectionRecord.checkout(pool)
532, in checkout
rec = pool._do_get()
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/pool.py", line
rec = pool._do_get()
1182, in _do_get
(self.size(), self.overflow(), self._timeout), code="3o7r")
sqlalchemy.exc.TimeoutError: QueuePool limit of size 1 overflow 0
reached, connection timed out, timeout 30 (Background on this error
at: http://sqlalche.me/e/3o7r)
>
> What do you think?
>
> Best regards,
> Stefan
>
> SQLAlchemy -
> The Python SQL Toolkit and Object Relational Mapper
>
> http://www.sqlalchemy.org/
>
> To post example code, please provide an MCVE: Minimal, Complete, and Verifiable Example. See http://stackoverflow.com/help/mcve for a full description.
> ---
> You received this message because you are subscribed to the Google Groups "sqlalchemy" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy+...@googlegroups.com.
> To post to this group, send email to sqlal...@googlegroups.com.
> Visit this group at https://groups.google.com/group/sqlalchemy.
> For more options, visit https://groups.google.com/d/optout.
Stefan Schwarzer
Feb 21, 2018, 2:34:37 PM2/21/18
to sqlalchemy
Thanks for the quick reply!
On Wednesday, February 21, 2018 at 6:44:33 PM UTC+1, Mike Bayer wrote:
I can come up with other things that can break based on the idea that
you're doing a full connection + execute sequence within the log
handler deep within that engine's own processes, such as, it can cause
connection pool exhaustion when you're working with the last
connection available, then your logger has no connection, it goes to
get one and...hang. I can reproduce this with your script (set
pool_size=1, max_overflow=0, set up logging and run an execute() so it
actually logs, and it hangs for 30 seconds until the timeout and
crashes, see stack trace below), so your approach is not safe in any
case.
Thanks for the clarification.
It would be a lot simpler and robust if your log handler just used its
own Engine (make a new one from the engine.url you already have).
Good idea.
That way you can lose all that re-entrant mutex stuff too.
The mutex stuff is there because in the actual code SQLAlchemy logging is switched on and I want to prevent that SQLAlchemy tries to log the insert statement in `_emit`. I didn't think of this when I posted the original question, so I could have left out the mutex stuff for the sake of the example code.
Best regards,
Stefan
Mike Bayer
Feb 21, 2018, 4:30:55 PM2/21/18
to sqlal...@googlegroups.com
from sqlalchemy import create_engine
import logging
logging.basicConfig()
logging.getLogger("sqlalchemy.engine").setLevel(logging.INFO)
e = create_engine("sqlite://")
e.scalar("select 1")
print("no more logging")
e = create_engine("sqlite://", logging_name="log_only")
logging.getLogger("sqlalchemy.engine.base.Engine.log_only").setLevel(logging.WARN)
e.scalar("select 1")
the ".base" module in the path there is slightly non-standard but
shouldn't be changing anytime soon.
Mike Bayer
Feb 21, 2018, 4:31:30 PM2/21/18
to sqlal...@googlegroups.com
or have your logger look for that "log_only" token in the logger name
and skip on that, that's more future-proof.
and skip on that, that's more future-proof.
Stefan Schwarzer
Feb 23, 2018, 3:11:58 PM2/23/18
to sqlalchemy
On Wednesday, February 21, 2018 at 10:31:30 PM UTC+1, Mike Bayer wrote:
or have your logger look for that "log_only" token in the logger name
and skip on that, that's more future-proof.
Yes, using a specific logger for the engine seems to work. :-)
I had looked for something like this, but didn't find it. I found http://docs.sqlalchemy.org/en/latest/core/engines.html#configuring-logging , but didn't see anything there on engine-specific logging names, so I thought it wasn't possible. (The `logging_name` argument for `create_engine` _is_ documented though.)
Best regards,
Stefan
Reply all
Reply to author
Forward
0 new messages