On Wed, Feb 21, 2018 at 7:16 AM, Stefan Schwarzer
<[email protected]> wrote:
> In our project we recently ran into the problem that SQLAlchemy would
> block when creating a connection for logging to a database.
>
>
> 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))
>
> 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
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):
File "test.py", line 134, in <module>
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",
line 1104, in _execute_text
statement, parameters
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py",
line 1151, in _execute_context
self.engine.logger.info(statement)
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",
line 2123, in contextual_connect
self._wrap_pool_connect(self.pool.connect, None),
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/engine/base.py",
line 2158, in _wrap_pool_connect
return fn()
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/pool.py", line
403, in connect
return _ConnectionFairy._checkout(self)
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/pool.py", line
784, in _checkout
fairy = _ConnectionRecord.checkout(pool)
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/pool.py", line
532, in checkout
rec = pool._do_get()
File "/home/classic/dev/sqlalchemy/lib/sqlalchemy/pool.py", line
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 [email protected].
> To post to this group, send email to [email protected].
> Visit this group at https://groups.google.com/group/sqlalchemy.
> For more options, visit https://groups.google.com/d/optout.
--
SQLAlchemy -
The Python SQL Toolkit and Object Relational Mapper
http://www.sqlalchemy.org/
To post example code, please provide an MCVE: Minimal, Complete, and Verifiable
Example. See http://stackoverflow.com/help/mcve for a full description.
---
You received this message because you are subscribed to the Google Groups
"sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To post to this group, send email to [email protected].
Visit this group at https://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.
