Re: [sqlalchemy] SQLAlchemy lock-up when logging to a database

[Mike Bayer]

or have your logger look for that "log_only" token in the logger name
and skip on that, that's more future-proof.

On Wed, Feb 21, 2018 at 4:30 PM, Mike Bayer  wrote:
> On Wed, Feb 21, 2018 at 2:34 PM, Stefan Schwarzer
>  wrote:
>> 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.
>
> but it wont, if you disable your logger engine from actually logging:
>
> 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.
>
>
>>
>> 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.

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

Re: [sqlalchemy] SQLAlchemy lock-up when logging to a database

[Mike Bayer]

On Wed, Feb 21, 2018 at 2:34 PM, Stefan Schwarzer
 wrote:
> 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.

but it wont, if you disable your logger engine from actually logging:

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.


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

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

Re: [sqlalchemy] SQLAlchemy lock-up when logging to a database

[Stefan Schwarzer]

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

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

Re: [sqlalchemy] SQLAlchemy lock-up when logging to a database

[Mike Bayer]

On Wed, Feb 21, 2018 at 7:16 AM, Stefan Schwarzer
 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 
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 

Re: [sqlalchemy] Problems with versioning when using a class mapped on a select of a table in SQLAlchemy 1.2

[Mike Bayer]

On Wed, Feb 21, 2018 at 10:04 AM, Mike Bayer  wrote:
> On Wed, Feb 21, 2018 at 6:33 AM, Jeff Horemans  wrote:
>> When migrating from 1.1 tot 1.2, we noticed that the version_id is not
>> getting set on a class that maps to a select of a table.
>> I've added a test case class below to the test_versioning.py included in
>> SQLAlchemy to confirm this behaviour.
>> This case runs fine in versions 1.0 and 1.1, but gives a KeyError on the
>> version_id in 1.2 as shown in the stack traces below.
>>
>> I'll be happy to make an issue on the repository if needed.
>
> no need, this is completely perfect, I'll create the issue.  I hope to
> get this into 1.2.4 which I need to release hopefully this week /
> today preferred (but I've wanted to release for two days already, ran
> out of time).   thanks!

this is 
https://bitbucket.org/zzzeek/sqlalchemy/issues/4193/versioning-logic-fails-for-mapping-against
, where you'll note that I found two more issues with versioning and
mappers to select statements, which you've already been working
around.  this is not a use case we tested for.


>
>
>>
>> class VersioningSelectTest(fixtures.MappedTest):
>>
>> __backend__ = True
>>
>> @classmethod
>> def define_tables(cls, metadata):
>> Table('version_table', metadata,
>>   Column('id', Integer, primary_key=True,
>>  test_needs_autoincrement=True),
>>   Column('version_id', Integer, nullable=False),
>>   Column('value', String(40), nullable=False))
>>
>> @classmethod
>> def setup_classes(cls):
>> class Foo(cls.Basic):
>> pass
>>
>> def _fixture(self):
>> Foo, version_table = self.classes.Foo, self.tables.version_table
>>
>> current = version_table.select().where(version_table.c.id >
>> 0).alias('current_table')
>>
>> mapper(Foo, current, version_id_col=version_table.c.version_id)
>> s1 = Session()
>> return s1
>>
>> @testing.emits_warning(r".*versioning cannot be verified")
>> def test_multiple_updates(self):
>> Foo = self.classes.Foo
>>
>> s1 = self._fixture()
>> f1 = Foo(value='f1')
>> f2 = Foo(value='f2')
>> s1.add_all((f1, f2))
>> s1.commit()
>>
>> f1.value = 'f1rev2'
>> f2.value = 'f2rev2'
>> s1.commit()
>>
>> eq_(
>> s1.query(Foo.id, Foo.value,
>> Foo.version_id).order_by(Foo.id).all(),
>> [(f1.id, 'f1rev2', 2), (f2.id, 'f2rev2', 2)]
>> )
>>
>>
>>
>> FAIL
>> test/orm/test_versioning.py::VersioningSelectTest_postgresql+psycopg2_9_5_11::()::test_multiple_updates
>>
>> == FAILURES
>> ==
>> ___
>> VersioningSelectTest_postgresql+psycopg2_9_5_11.test_multiple_updates
>> 
>> Traceback (most recent call last):
>>   File
>> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/orm/test_versioning.py",
>> line 131, in test_multiple_updates
>> s1.commit()
>>   File
>> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
>> line 943, in commit
>> self.transaction.commit()
>>   File
>> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
>> line 467, in commit
>> self._prepare_impl()
>>   File
>> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
>> line 447, in _prepare_impl
>> self.session.flush()
>>   File
>> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
>> line 2243, in flush
>> self._flush(objects)
>>   File
>> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
>> line 2369, in _flush
>> transaction.rollback(_capture_exception=True)
>>   File
>> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/util/langhelpers.py",
>> line 66, in __exit__
>> compat.reraise(exc_type, exc_value, exc_tb)
>>   File
>> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
>> line 2333, in _flush
>> flush_context.execute()
>>   File
>> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/unitofwork.py",
>> line 391, in execute
>> rec.execute(self)
>>   File
>> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/unitofwork.py",
>> line 556, in execute
>> uow
>>   File
>> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/persistence.py",
>> line 193, in save_obj
>> update_version_id in states_to_update
>>   File

Re: [sqlalchemy] Problems with versioning when using a class mapped on a select of a table in SQLAlchemy 1.2

[Mike Bayer]

On Wed, Feb 21, 2018 at 6:33 AM, Jeff Horemans  wrote:
> When migrating from 1.1 tot 1.2, we noticed that the version_id is not
> getting set on a class that maps to a select of a table.
> I've added a test case class below to the test_versioning.py included in
> SQLAlchemy to confirm this behaviour.
> This case runs fine in versions 1.0 and 1.1, but gives a KeyError on the
> version_id in 1.2 as shown in the stack traces below.
>
> I'll be happy to make an issue on the repository if needed.

no need, this is completely perfect, I'll create the issue.  I hope to
get this into 1.2.4 which I need to release hopefully this week /
today preferred (but I've wanted to release for two days already, ran
out of time).   thanks!


>
> class VersioningSelectTest(fixtures.MappedTest):
>
> __backend__ = True
>
> @classmethod
> def define_tables(cls, metadata):
> Table('version_table', metadata,
>   Column('id', Integer, primary_key=True,
>  test_needs_autoincrement=True),
>   Column('version_id', Integer, nullable=False),
>   Column('value', String(40), nullable=False))
>
> @classmethod
> def setup_classes(cls):
> class Foo(cls.Basic):
> pass
>
> def _fixture(self):
> Foo, version_table = self.classes.Foo, self.tables.version_table
>
> current = version_table.select().where(version_table.c.id >
> 0).alias('current_table')
>
> mapper(Foo, current, version_id_col=version_table.c.version_id)
> s1 = Session()
> return s1
>
> @testing.emits_warning(r".*versioning cannot be verified")
> def test_multiple_updates(self):
> Foo = self.classes.Foo
>
> s1 = self._fixture()
> f1 = Foo(value='f1')
> f2 = Foo(value='f2')
> s1.add_all((f1, f2))
> s1.commit()
>
> f1.value = 'f1rev2'
> f2.value = 'f2rev2'
> s1.commit()
>
> eq_(
> s1.query(Foo.id, Foo.value,
> Foo.version_id).order_by(Foo.id).all(),
> [(f1.id, 'f1rev2', 2), (f2.id, 'f2rev2', 2)]
> )
>
>
>
> FAIL
> test/orm/test_versioning.py::VersioningSelectTest_postgresql+psycopg2_9_5_11::()::test_multiple_updates
>
> == FAILURES
> ==
> ___
> VersioningSelectTest_postgresql+psycopg2_9_5_11.test_multiple_updates
> 
> Traceback (most recent call last):
>   File
> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/orm/test_versioning.py",
> line 131, in test_multiple_updates
> s1.commit()
>   File
> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
> line 943, in commit
> self.transaction.commit()
>   File
> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
> line 467, in commit
> self._prepare_impl()
>   File
> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
> line 447, in _prepare_impl
> self.session.flush()
>   File
> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
> line 2243, in flush
> self._flush(objects)
>   File
> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
> line 2369, in _flush
> transaction.rollback(_capture_exception=True)
>   File
> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/util/langhelpers.py",
> line 66, in __exit__
> compat.reraise(exc_type, exc_value, exc_tb)
>   File
> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
> line 2333, in _flush
> flush_context.execute()
>   File
> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/unitofwork.py",
> line 391, in execute
> rec.execute(self)
>   File
> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/unitofwork.py",
> line 556, in execute
> uow
>   File
> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/persistence.py",
> line 193, in save_obj
> update_version_id in states_to_update
>   File
> "/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/persistence.py",
> line 1131, in _finalize_insert_update_commands
> if state_dict[mapper._version_id_prop.key] is None:
> KeyError: u'version_id
>
> --
> 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 

Re: [sqlalchemy] Session's dialect's server_version_info may be None? (Execution order dependency)

[Mike Bayer]

it's not unheard of that people sometimes do a quick ping, like :

engine = create_engine(...)
engine.scalar("select 1")

just to get it connected and initialized with server information.



On Wed, Feb 21, 2018 at 6:26 AM,   wrote:
> Simon, thank you for the reference! That makes sense…
>
> Jens
>
>
> On Wednesday, February 21, 2018 at 7:15:20 PM UTC+10, Simon King wrote:
>>
>> SQLAlchemy doesn't connect to the database until it needs to. Creating
>> a Session by itself does not cause it to connect. This is mentioned in
>> the docs:
>>
>> http://docs.sqlalchemy.org/en/latest/orm/session_basics.html
>>
>> """
>> The Session begins in an essentially stateless form. Once queries are
>> issued or other objects are persisted with it, it requests a
>> connection resource from an Engine that is associated either with the
>> Session itself or with the mapped Table objects being operated upon.
>> This connection represents an ongoing transaction, which remains in
>> effect until the Session is instructed to commit or roll back its
>> pending state.
>> """
>>
>> Hope that helps,
>>
>> Simon
>
> --
> 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.

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

[sqlalchemy] SQLAlchemy lock-up when logging to a database

[Stefan Schwarzer]

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 

[sqlalchemy] Problems with versioning when using a class mapped on a select of a table in SQLAlchemy 1.2

[Jeff Horemans]

When migrating from 1.1 tot 1.2, we noticed that the version_id is not 
getting set on a class that maps to a select of a table.
I've added a test case class below to the test_versioning.py included in 
SQLAlchemy to confirm this behaviour.
This case runs fine in versions 1.0 and 1.1, but gives a KeyError on the 
version_id in 1.2 as shown in the stack traces below.

I'll be happy to make an issue on the repository if needed.

class VersioningSelectTest(fixtures.MappedTest):

__backend__ = True

@classmethod
def define_tables(cls, metadata):
Table('version_table', metadata,
  Column('id', Integer, primary_key=True,
 test_needs_autoincrement=True),
  Column('version_id', Integer, nullable=False),
  Column('value', String(40), nullable=False))  

@classmethod
def setup_classes(cls):
class Foo(cls.Basic):
pass 

def _fixture(self):
Foo, version_table = self.classes.Foo, self.tables.version_table

current = version_table.select().where(version_table.c.id > 0).alias
('current_table')

mapper(Foo, current, version_id_col=version_table.c.version_id)
s1 = Session()
return s1

@testing.emits_warning(r".*versioning cannot be verified")
def test_multiple_updates(self):
Foo = self.classes.Foo

s1 = self._fixture()
f1 = Foo(value='f1')
f2 = Foo(value='f2')
s1.add_all((f1, f2))
s1.commit()

f1.value = 'f1rev2'
f2.value = 'f2rev2'
s1.commit()

eq_(
s1.query(Foo.id, Foo.value, Foo.version_id).order_by(Foo.id).all
(),
[(f1.id, 'f1rev2', 2), (f2.id, 'f2rev2', 2)]
)



FAIL 
test/orm/test_versioning.py::VersioningSelectTest_postgresql+psycopg2_9_5_11::()::test_multiple_updates

== FAILURES 
==
___ 
VersioningSelectTest_postgresql+psycopg2_9_5_11.test_multiple_updates 

Traceback (most recent call last):
  File 
"/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/orm/test_versioning.py",
 
line 131, in test_multiple_updates
s1.commit()
  File 
"/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
 
line 943, in commit
self.transaction.commit()
  File 
"/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
 
line 467, in commit
self._prepare_impl()
  File 
"/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
 
line 447, in _prepare_impl
self.session.flush()
  File 
"/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
 
line 2243, in flush
self._flush(objects)
  File 
"/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
 
line 2369, in _flush
transaction.rollback(_capture_exception=True)
  File 
"/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/util/langhelpers.py",
 
line 66, in __exit__
compat.reraise(exc_type, exc_value, exc_tb)
  File 
"/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/session.py",
 
line 2333, in _flush
flush_context.execute()
  File 
"/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/unitofwork.py",
 
line 391, in execute
rec.execute(self)
  File 
"/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/unitofwork.py",
 
line 556, in execute
uow
  File 
"/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/persistence.py",
 
line 193, in save_obj
update_version_id in states_to_update
  File 
"/home/jeffh/vortex-workspace/v-finance/subrepos/SQLAlchemy-1.2.3/test/../lib/sqlalchemy/orm/persistence.py",
 
line 1131, in _finalize_insert_update_commands
if state_dict[mapper._version_id_prop.key] is None:
KeyError: u'version_id

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

Re: [sqlalchemy] Session's dialect's server_version_info may be None? (Execution order dependency)

[jens . troeger]

Simon, thank you for the reference! That makes sense…

Jens


On Wednesday, February 21, 2018 at 7:15:20 PM UTC+10, Simon King wrote:
>
> SQLAlchemy doesn't connect to the database until it needs to. Creating 
> a Session by itself does not cause it to connect. This is mentioned in 
> the docs: 
>
> http://docs.sqlalchemy.org/en/latest/orm/session_basics.html 
>
> """ 
> The Session begins in an essentially stateless form. Once queries are 
> issued or other objects are persisted with it, it requests a 
> connection resource from an Engine that is associated either with the 
> Session itself or with the mapped Table objects being operated upon. 
> This connection represents an ongoing transaction, which remains in 
> effect until the Session is instructed to commit or roll back its 
> pending state. 
> """ 
>
> Hope that helps, 
>
> Simon 
>

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

Re: [sqlalchemy] Session's dialect's server_version_info may be None? (Execution order dependency)

[Simon King]

On Wed, Feb 21, 2018 at 6:14 AM,   wrote:
> Hello,
> Suppose I create a db session the normal way:
>
 engine = engine_from_config({"sqlalchemy.url":"mysql+pymysql://…"})
 Session = sessionmaker(bind=engine)
 session = Session()
>
> I noticed that there is now an order dependency between:
>
 session.bind.dialect.server_version_info  # None
 session.query(Alembic.version_num).scalar()
> 'cb13f97d30c6'
 session.bind.dialect.server_version_info  # Now contains a tuple
> (5, 6, 34)
>
> I can't quite make sense of this behavior, can somebody please shed some
> light on it?
>

SQLAlchemy doesn't connect to the database until it needs to. Creating
a Session by itself does not cause it to connect. This is mentioned in
the docs:

http://docs.sqlalchemy.org/en/latest/orm/session_basics.html

"""
The Session begins in an essentially stateless form. Once queries are
issued or other objects are persisted with it, it requests a
connection resource from an Engine that is associated either with the
Session itself or with the mapped Table objects being operated upon.
This connection represents an ongoing transaction, which remains in
effect until the Session is instructed to commit or roll back its
pending state.
"""

Hope that helps,

Simon

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