0.5.2 seems to always roll back with mssql

[davidlmontgomery]

I'm using sqlalchemy with sql server express. Client-side
is also Windows, running python 2.5.2.

I find that all my changes get rolled back when using
0.5.2. But using 0.4.8, things work as I expect.

Here is an example script:

--- start script ---
import datetime
import sqlalchemy
from sqlalchemy.orm import scoped_session, sessionmaker

print "sqlalchemy version:", sqlalchemy.__version__

conn_str = 'mssql://<user>:<password>@<server>/<database>?dsn=<dsn>'
mssql_engine = sqlalchemy.create_engine(conn_str)
mssql_metadata = sqlalchemy.MetaData(bind=mssql_engine)
MSSQLSession = scoped_session(sessionmaker(bind=mssql_metadata.bind))

data = 'bingo'
now = datetime.datetime.now()
time = now.strftime('%Y-%m-%d %H:%M:%S')
command = "INSERT sa_test (data, time) VALUES ('%s', '%s')" % (data,
time)

session = MSSQLSession()
session.execute(command)
session.commit()

command = "SELECT COUNT(*) FROM sa_test WHERE data='%s'" % data

session = MSSQLSession()
print "count:", session.execute(command).scalar()

MSSQLSession.remove()
--- end script ---

Running this I'll get "count: 1" (assuming a clean sa_test table),
showing
that the insert occurred. But then looking in the database, I'll see
that
the data aren't there (with 0.5.2; with 0.4.8 the data will be there).

The same thing happens with updates.

It appears to me that the session.commit() call isn't working
with 0.5.2. I think the transaction is staying open until the call
to MSSQLSession.remove(), which rolls everything back.

Some evidence of that ... If I add the line

raw_input("Enter to exit.")

before the MSSQLSession.remove(), and then while paused there
I go to a query window in sql server express, if I'm using 0.5.2 I'll
find that queries against the table hang -- presumably waiting for
the transaction to finish. But with 0.4.8 this has no effect -- the
changes have already been committed.

Thanks for any help resolving this.

David

[Mike Conley]

Have you tried adding echo=True to the engine to observe the actual SQL?

--
Mike Conley

[Michael Bayer]

On Mar 20, 2009, at 8:23 PM, davidlmontgomery wrote:

> Running this I'll get "count: 1" (assuming a clean sa_test table),
> showing
> that the insert occurred. But then looking in the database, I'll see
> that
> the data aren't there (with 0.5.2; with 0.4.8 the data will be there).
>
> The same thing happens with updates.
>
> It appears to me that the session.commit() call isn't working
> with 0.5.2. I think the transaction is staying open until the call
> to MSSQLSession.remove(), which rolls everything back.

remove() will roll back any existing transaction but the commit() call
previously will issue a COMMIT for any pending data. the COMMIT will
show up in your SQL logs so check those out. theres no logic in the
MSSQL engine that would specifically affect this.

however I notice that your INSERT statement is incorrect:

> command = "INSERT sa_test (data, time) VALUES ('%s', '%s')" % (data,
> time)

I'm not sure if that's an MSSQL specific syntax but its invalid in SQL
in general (the "INTO" keyword is missing), so that might be the
source of your issue.

[davidlmontgomery]

Thanks Mike and Michael for your suggestions.

> remove() will roll back any existing transaction

Yes, this is what I am seeing.

> but the commit() call
> previously will issue a COMMIT for any pending data.

And this COMMIT is succeeding with 0.4.8, but it is not
succeeding with 0.5.2.

> the COMMIT will
> show up in your SQL logs so check those out.

I see the COMMIT in the logs for both 0.4.8 and
0.5.2. With 0.4.8 it works, and the table is unlocked
immediately after the COMMIT. In 0.5.2, the table
stays locked after the COMMIT, until the call to
session.remove(). Something is going awry with the
0.5.2 COMMIT.

> theres no logic in the
> MSSQL engine that would specifically affect this.

I guess I'll set a breakpoint where I issue the
COMMIT -- or perhaps near where the COMMIT log
message is issued, if I can easily find that -- and see
if I can come to some understanding of the difference.

Any hints for my spelunking would be appreciated.
If I can't figure it out fairly soon I'll just need to revert
to 0.4.8.

Here is a revised test script:

--- test script ---

import datetime
import sqlalchemy
from sqlalchemy.orm import scoped_session, sessionmaker

print "sqlalchemy version:", sqlalchemy.__version__

conn_str = 'mssql://<user>:<password>@<server>/<database>?dsn=<dsn>'

mssql_engine = sqlalchemy.create_engine(conn_str, echo=True)

mssql_metadata = sqlalchemy.MetaData(bind=mssql_engine)
MSSQLSession = scoped_session(sessionmaker(bind=mssql_metadata.bind))

data = 'bingo'
now = datetime.datetime.now()
time = now.strftime('%Y-%m-%d %H:%M:%S')

command = "INSERT INTO sa_test (data, time) VALUES ('%s', '%s')" %
(data, time)

session = MSSQLSession()
session.execute(command)
session.commit()

command = "SELECT COUNT(*) FROM sa_test WHERE data='%s'" % data

session = MSSQLSession()

count = session.execute(command).scalar()
print "count:", count

MSSQLSession.remove()
--- end test script ---

This gets the same behavior as before. I'm seeing the
same behavior with INSERTs, UPDATEs, and (in the
context of the source application) sprocs that themselves
do a bunch of INSERTs and/or UPDATEs.

Here are sample runs (I've wrapped the output lines
manually):

--- first run with 0.5.2 ---
sqlalchemy version: 0.5.2
2009-03-21 16:22:51,403 INFO
sqlalchemy.engine.base.Engine.0x...fb30
BEGIN
2009-03-21 16:22:51,434 INFO
sqlalchemy.engine.base.Engine.0x...fb30
INSERT INTO sa_test (data, time)
VALUES ('bingo', '2009-03-21 16:22:51')
2009-03-21 16:22:51,436 INFO
sqlalchemy.engine.base.Engine.0x...fb30
[]
2009-03-21 16:22:51,453 INFO
sqlalchemy.engine.base.Engine.0x...fb30
COMMIT
2009-03-21 16:22:51,470 INFO
sqlalchemy.engine.base.Engine.0x...fb30
BEGIN
2009-03-21 16:22:51,502 INFO
sqlalchemy.engine.base.Engine.0x...fb30
SELECT COUNT(*) FROM sa_test WHERE data='bingo'
2009-03-21 16:22:51,503 INFO
sqlalchemy.engine.base.Engine.0x...fb30
[]
count: 1

[1 would be correct, but table actually still has 0]

--- second run with 0.5.2 ---
sqlalchemy version: 0.5.2
2009-03-21 16:22:53,035 INFO
sqlalchemy.engine.base.Engine.0x...0b30
BEGIN
2009-03-21 16:22:53,065 INFO
sqlalchemy.engine.base.Engine.0x...0b30
INSERT INTO sa_test (data, time)
VALUES ('bingo', '2009-03-21 16:22:52')
2009-03-21 16:22:53,069 INFO
sqlalchemy.engine.base.Engine.0x...0b30
[]
2009-03-21 16:22:53,085 INFO
sqlalchemy.engine.base.Engine.0x...0b30
COMMIT
2009-03-21 16:22:53,101 INFO
sqlalchemy.engine.base.Engine.0x...0b30
BEGIN
2009-03-21 16:22:53,132 INFO
sqlalchemy.engine.base.Engine.0x...0b30
SELECT COUNT(*) FROM sa_test WHERE data='bingo'
2009-03-21 16:22:53,135 INFO
sqlalchemy.engine.base.Engine.0x...0b30
[]
count: 1

[table still has 0 -- 0.5.2 is always rolling back]

--- first run with 0.4.8 ---
sqlalchemy version: 0.4.8
2009-03-21 16:23:46,415 INFO
sqlalchemy.engine.base.Engine.0b30
BEGIN
2009-03-21 16:23:46,417 INFO
sqlalchemy.engine.base.Engine.0b30
INSERT INTO sa_test (data, time)
VALUES ('bingo', '2009-03-21 16:23:46')
2009-03-21 16:23:46,420 INFO
sqlalchemy.engine.base.Engine.0b30
{}
2009-03-21 16:23:46,448 INFO
sqlalchemy.engine.base.Engine.0b30
COMMIT
2009-03-21 16:23:46,469 INFO
sqlalchemy.engine.base.Engine.0b30
BEGIN
2009-03-21 16:23:46,470 INFO
sqlalchemy.engine.base.Engine.0b30
SELECT COUNT(*) FROM sa_test WHERE data='bingo'
2009-03-21 16:23:46,473 INFO
sqlalchemy.engine.base.Engine.0b30
{}
count: 1

[correct: table now does have 1]

--- first run with 0.4.8 ---
sqlalchemy version: 0.4.8
2009-03-21 16:25:27,819 INFO
sqlalchemy.engine.base.Engine.0b30
BEGIN
2009-03-21 16:25:27,821 INFO
sqlalchemy.engine.base.Engine.0b30
INSERT INTO sa_test (data, time)
VALUES ('bingo', '2009-03-21 16:25:27')
2009-03-21 16:25:27,822 INFO
sqlalchemy.engine.base.Engine.0b30
{}
2009-03-21 16:25:27,839 INFO
sqlalchemy.engine.base.Engine.0b30
COMMIT
2009-03-21 16:25:27,858 INFO
sqlalchemy.engine.base.Engine.0b30
BEGIN
2009-03-21 16:25:27,859 INFO
sqlalchemy.engine.base.Engine.0b30
SELECT COUNT(*) FROM sa_test WHERE data='bingo'
2009-03-21 16:25:27,861 INFO
sqlalchemy.engine.base.Engine.0b30
{}
count: 2

[correct: table now does have 2]

[davidlmontgomery]

Tracing through the code from the point of commit
didn't help. Both 0.4.8 and 0.5.2 follow essentially
the same (perhaps exactly the same, but I didn't
check that 100%) path down to a call to a
built-in method commit of the pyodbc.Connection
object.

In my test script I am getting correct behavior for
0.5.2 if I pass autocommit=True to sessionmaker.

Unfortunately neither autocommit=True with 0.5.2
or transactional=False with 0.4.8 work in my actual
application.

David

[Michael Bayer]

Ive booted up my virtual windows machine and it all works for me.
note that "dsn" is now the default interpretation of host in 0.5, i.e.
connect using mssql://<dsn>. perhaps you've got multiple database
instances being accesed across SQLA versions.

[davidlmontgomery]

Thanks Michael for looking into it.

I've verified that I get the same results (works with 0.4.8,
rolls back with 0.5.2) on two additional Windows client
machines. Different OS's and python versions, so it's a
stable result on my end.

I'm not sure the best way to dig into this further. I'm going
to take a look at some tools I saw recommended recently
for looking at what is going across the wire to see if I can
learn something there.

(I did try the mssql://<dsn> for 0.5.2, but got the same results.)

David

[Michael Bayer]

what if you create the same table on a totally new database and run it
there ?

[davidlmontgomery]

On Mar 24, 2:40 pm, "Michael Bayer" <mike...@zzzcomputing.com> wrote:
> what if you create the same table on a totally new database and run it
> there ?

Good idea. I'll try that momentarily.

In the meantime, I tried out wireshark and see that there
is a reliable difference in what is getting sent.

With 0.5.2 what gets sent is this:

Query: set implicit_transactions on
RPC Name: sp_datatype_info
Query: SET IMPLICIT_TRANSACTIONS OFF
Query: BEGIN TRANSACTION
Query: INSERT INTO sa_test (data, time) VALUES ('bingo',
'2009-03-24 14:57:58')
Query: IF @@TRANCOUNT > 0 COMMIT TRAN
Query: SET IMPLICIT_TRANSACTIONS OFF
Query: BEGIN TRANSACTION
Query: SELECT COUNT(*) FROM sa_test WHERE data='bingo'
Query: IF @@TRANCOUNT > 0 ROLLBACK TRAN

With 0.4.8 what gets sent is this:

Query: set implicit_transactions on
RPC Name: sp_datatype_info
Query: INSERT INTO sa_test (data, time) VALUES ('bingo',
'2009-03-24 14:57:58')
Query: IF @@TRANCOUNT > 0 COMMIT TRAN
Query: BEGIN TRANSACTION
Query: SELECT COUNT(*) FROM sa_test WHERE data='bingo'
Query: IF @@TRANCOUNT > 0 ROLLBACK TRAN

Note that with 0.4.8 the TDS data sent relies on
IMPLICIT_TRANSACTIONS being set ON, while
with 0.5.2, this gets turned OFF, and then BEGIN
TRANSACTIONs are sent.

David

[davidlmontgomery]

Oops, I messed up the 0.4.8 data as I was
cutting and pasting.

Corrected, actual data sent by 0.4.8:

Query: set implicit_transactions on
RPC Name: sp_datatype_info
Query: INSERT INTO sa_test (data, time) VALUES ('bingo',

'2009-03-24 15:08:12')

Query: IF @@TRANCOUNT > 0 COMMIT TRAN

Query: SELECT COUNT(*) FROM sa_test WHERE data='bingo'
Query: IF @@TRANCOUNT > 0 ROLLBACK TRAN

So, no BEGIN TRANSACTION (or SET
IMPLICIT_TRANSACTIONS OFF).

On Mar 24, 3:31 pm, davidlmontgomery <davidlmontgom...@gmail.com>
wrote:

[Michael Bayer]

ah. so thats a difference. ticket 1350 is added, we'll see what
the MS-SQL crew has to say.

[davidlmontgomery]

The relevant change is the addition of the
MSSQLDialect.do_begin method:

def do_begin(self, connection):
cursor = connection.cursor()
cursor.execute("SET IMPLICIT_TRANSACTIONS OFF")
cursor.execute("BEGIN TRANSACTION")

This was first introduced three months ago
to correct the savepoint tests
http://bitbucket.org/mirror/sqlalchemy/changeset/985925326dc8/

and revised a couple months ago to use the
cursor rather than the connection:
http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/lib/sqlalchemy/databases/mssql.py?rev=5641

With this method converted to a pass, 0.5.2 works
properly for me on the three machines where before
it always rolled back.

David

[Michael Bayer]

yeah I know when it was done. we need Michael to fill in on that
detail.

[Michael Bayer]

so in your app, you can do this for now to monkeypatch the problem away:

engine.dialect.do_begin = lambda *arg, **kw: pass

the current steps in do_begin() are probably needed for savepoint
support, though I might try myself at the pycon sprints to isolate
exactly why, and if so we'd have to regulate that operation based on
some kind of engine flag (most likely enable_savepoint=True, something
like that).

On Mar 24, 2009, at 8:09 PM, davidlmontgomery wrote:

>

[Michael Trier]

Yeah that code was added to fix savepoint support.  One of the problems with MSSQL with Implicit Transactions is that it only gets turned on once a DML statement gets executed.  Unfortunately issuing a savepoint doesn't turn on the implicit transaction.  Therefore we were in a situation where there was no begin transaction, but there was a savepoint issued.  Originally we tried to implement this by keeping implicit transactions but checking at the time the savepoint was issued to begin the transaction if it wasn't present.  That had issues and honestly I can't recall what it was.  The way it is structured now seems to work fine in all the tests, so it's odd that you're having a problem.  My only guess is that it's a TDS thing (I believe you said you were using that).  The odd thing is that the list of items you're seeing across the wire is exactly what I'm getting as well and what should be expected.

--
Michael Trier
http://blog.michaeltrier.com/
http://thisweekindjango.com/

[davidlmontgomery]

On Mar 24, 5:50 pm, Michael Trier <mtr...@gmail.com> wrote:
> The way it is
> structured now seems to work fine in all the tests, so it's odd that you're
> having a problem. My only guess is that it's a TDS thing (I believe you
> said you were using that). The odd thing is that the list of items you're
> seeing across the wire is exactly what I'm getting as well and what should
> be expected.

I don't know this well enough to have any insights.
If there are some sorts of tests or investigations you'd
like me to run to gather more information, let me know.

I only said TDS because that's what Wireshark labeled
the protocol for the packets where this data was being sent.

David

[Rick Morrison]

Jeez, yet another wonky mssql behavior switch?  That things got more flags than the U.N.

I believe that the MSSQL ODBC driver on Windows automatically sets IMPLICIT_TRANSACTION off on connect, whereas FreeTDS likely does not, which is perhaps the source of the problem.

Here's what I think the problem might be:
   - The code the OP posted has no initial .begin(), so the program starts with a random IMPLICIT_TRANSACTION state depending upon ODBC driver + server settings.
   - For FreeTDS and his server, let's assume IMPLICIT_TRANSACTION is ON
   - The session.execute() then issues a BEGIN (since the session is not in autocommit mode)
   - If the server started in IMPLICIT_TRANSACTION mode, the @@TRANCOUNT would now be TWO, not one (one implicit, one explicit)
   - The next .commit() closes the second tx, now it's @@TRANCOUNT == 1
   - Another BEGIN and SELECT finds the inserted data, and returns it (hence the rowcount==1)
   - Another explicit COMMIT, @@TRANCOUNT again goes from 2 => 1
   - Program ends (with a rollback of the starting implicit transaction)
   - Data is now gone

It seems to me that the only time you'd want IMPLICIT_TRANSACTION on is in autocommit mode, where savepoints don't make any sense anyway.  Otherwise, since SQLA defaults to explicit transaction semantics everywhere, you'd want IMPLICIT_TRANSACTION turned OFF on initial connect and left off for the duration of the connection.

Is there a hook to execute setup SQL on connection establishment, or when a session claims a connection? If so, those might be the places to set that damned flag OFF. It could be tricky getting session autocommit vs. non-session SQL to work right on shared connections.

I would even be +1 on disallowing autocommit mode on MSSQL, since it complicates the connection setup vs. session connection claim logic so much.

Rick

[lurcher]

Hi,

I don't know if I can add any further to this, but I have just been
looking at this exact problem with our (Easysoft) SQL Server driver.
And one thing we have found is that you get different results
depending on which version of TDS the driver is using. If we use (for
the moment) the MS drivers on windows the code works as expected with
SQL Server drivers for 2000 and before, but with the new Native client
drivers (2000 sp3 and later) it fails to do the update as reported
above.

The problem seems to be the sequence

Query: set implicit_transactions on
RPC Name: sp_datatype_info
Query: SET IMPLICIT_TRANSACTIONS OFF
Query: BEGIN TRANSACTION

If the sp_datatype_info is not done, then it all works fine, but
because the sp_datatype_info a transaction is stated at this point,
and it seems that everything afterthis point is nested inside this
trasaction. So the commit works and commits the data, but the rollback
that occurs at the end rollsback (what I assume is) the outer
trasaction undoing the effect of the earlier insert and commit.

I in fact added a flag to our driver to allow the driver to force
2000 type TDS as a way around the problem. Our support team also found
that calling commit() after the connect also worked. I guess this will
close the outer transaction.

Nick

[Rick Morrison]

Yep, same here.

..on my mssql 2005, I tried this query batch:

"""
set implicit_transactions on
go
select 'After implicit ON', @@trancount

exec sp_datatype_info
go
select 'After query w/implicit', @@trancount

begin transaction
go
select 'After BEGIN', @@trancount
"""

Here's the output:

---------------------  ----
After implicit ON 0

---------------------------- ----
After query w/implicit  1

----------------  ----
After BEGIN  2

Our support team also found that calling commit() after the connect also worked. I guess this will
close the outer transaction.

It's a bit of a hack, but it sounds like a simple 2-cent solution. We could issue something like:

IF @@TRANCOUNT > 0
    COMMIT

on connection establishment.

Rick

[Lukasz Szybalski]

Joined in kind of late on this....but, what version of TDS are you
setting in your dsn setup? (Not sure if that makes a difference or
not)

Lucas