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
--
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.
