Re: Commit to odbc.c from 5/19/2010 breaks prepared statements with pyodbc
"Peter C. Norton" <[email protected]>
| Newsgroups | gmane.comp.db.tds.freetds |
|---|---|
| Message-ID | <[email protected]> |
Here's the trace, with the login packets, etc. missing. This is a test query against tempdb.dbo.tester:
CREATE TABLE tester
(
id int NOT NULL,
name varchar(20) NOT NULL
)
309:1> select * from tester
309:2> go
id name
----------- --------------------
1 test1
2 test2
(2 rows affected)
310:1>
Here is the TDS trace with identifying info removed, and a big chunk
of the login session removed, too. Let me know if I've removed
relevant data (hopefully not, though!):
log.c:196:Starting log file for FreeTDS 0.83.dev.20101015
on 2010-10-19 12:57:18 with debug flags 0x4fff.
iconv.c:337:tds_iconv_open(0x180cf160, ISO-8859-1)
iconv.c:197:local name for ISO-8859-1 is ISO-8859-1
iconv.c:197:local name for UTF-8 is UTF-8
iconv.c:197:local name for UCS-2LE is UCS-2LE
iconv.c:197:local name for UCS-2BE is UCS-2BE
iconv.c:365:setting up conversions for client charset "ISO-8859-1"
iconv.c:367:preparing iconv for "ISO-8859-1" <-> "UCS-2LE" conversion
iconv.c:408:preparing iconv for "ISO-8859-1" <-> "ISO-8859-1" conversion
iconv.c:411:tds_iconv_open: done
net.c:205:Connecting to XXX.XXX.XXX.XXX port 1400 (TDS version 5.0)
net.c:261:tds_open_socket: connect(2) returned "Operation now in progress"
net.c:301:tds_open_socket() succeeded
util.c:156:Changed query state from DEAD to IDLE
net.c:730:Sending packet
[...]
odbc.c:1717:SQLAllocStmt(0x180cd770, 0x180d8e80)
odbc.c:1616:_SQLAllocStmt(0x180cd770, 0x180d8e80)
odbc.c:4393:SQLGetStmtAttr(0x180d90e0, 10010, 0x7fff7aca9c68, 8, (nil))
odbc.c:4393:SQLGetStmtAttr(0x180d90e0, 10011, 0x7fff7aca9c68, 8, (nil))
odbc.c:4393:SQLGetStmtAttr(0x180d90e0, 10012, 0x7fff7aca9c68, 8, (nil))
odbc.c:4393:SQLGetStmtAttr(0x180d90e0, 10013, 0x7fff7aca9c68, 8, (nil))
odbc.c:4159:SQLFreeStmt(0x180d90e0, 0)
odbc.c:4080:_SQLFreeStmt(0x180d90e0, 0, 0)
odbc.c:4439:SQLPrepare(0x180d90e0, select * from tester where id = ?, -3)
odbc.c:4484:Creating prepared statement
mem.c:615:tds_free_all_results()
util.c:156:Changed query state from IDLE to QUERYING
util.c:156:Changed query state from QUERYING to PENDING
net.c:730:Sending packet
0000 0f 01 00 55 00 00 00 00-e7 4a 00 01 00 0a 79 38 |...U.... .J....y8|
0010 72 6d 38 39 36 30 30 30-3b 00 63 72 65 61 74 65 |rm896000 ;.create|
0020 20 70 72 6f 63 20 79 38-72 6d 38 39 36 30 30 30 | proc y8 rm896000|
0030 20 61 73 20 73 65 6c 65-63 74 20 2a 20 66 72 6f | as sele ct * fro|
0040 6d 20 74 65 73 74 65 72-20 77 68 65 72 65 20 69 |m tester where i|
0050 64 20 3d 20 3f - |d = ?|
token.c:539:tds_process_tokens(0x180cf160, 0x7fff7aca9a1c, 0x7fff7aca9a18, 0x104)
util.c:156:Changed query state from PENDING to READING
net.c:546:Received header
0000 04 01 00 7d 00 00 00 00- |...}....|
net.c:600:Received packet
0000 04 01 00 7d 00 00 00 00-e7 0d 00 20 00 0a 79 38 |...}.... ... ..y8|
0010 72 6d 38 39 36 30 30 30-20 0d 00 00 00 01 00 00 |rm896000 .......|
0020 00 00 00 00 00 00 00 00-38 00 61 45 00 00 00 02 |........ 8.aE....|
0030 00 00 06 74 65 6d 70 64-62 03 64 62 6f 06 74 65 |...tempd b.dbo.te|
0040 73 74 65 72 02 69 64 10-00 00 00 07 00 00 00 38 |ster.id. .......8|
0050 00 00 06 74 65 6d 70 64-62 03 64 62 6f 06 74 65 |...tempd b.dbo.te|
0060 73 74 65 72 04 6e 61 6d-65 10 00 00 00 02 00 00 |ster.nam e.......|
0070 00 27 14 00 fd 04 00 01-00 00 00 00 00 |.'...... .....|
token.c:554:processing result tokens. marker is e7(TDS5_DYNAMIC)
token.c:554:processing result tokens. marker is 20(TDS5_PARAMFMT2)
token.c:3053:elem 0:
token.c:3054: column_name=[]
token.c:3055: flags=0 utype=0 type=56 varint=0
token.c:3057: colsize=4 prec=0 scale=0
token.c:554:processing result tokens. marker is 61(ROWFMT2)
token.c:1831:tds5_process_result
mem.c:615:tds_free_all_results()
token.c:1855:num_cols=2
token.c:1958:col 0:
token.c:1959: column_name=[id]
token.c:1965: flags=10 utype=7 type=56 varint=0
token.c:1968: colsize=4 prec=0 scale=0
token.c:1958:col 1:
token.c:1959: column_name=[name]
token.c:1965: flags=10 utype=2 type=39 varint=1
token.c:1968: colsize=20 prec=0 scale=0
util.c:156:Changed query state from READING to PENDING
token.c:539:tds_process_tokens(0x180cf160, 0x7fff7aca9a1c, 0x7fff7aca9a18, 0x104)
util.c:156:Changed query state from PENDING to READING
token.c:554:processing result tokens. marker is fd(DONE)
token.c:2461:tds_process_end: more_results = 0
was_cancelled = 0
error = 0
done_count_valid = 0
token.c:2477:tds_process_end() state set to TDS_IDLE
util.c:156:Changed query state from READING to IDLE
token.c:2492: rows_affected = 0
util.c:104:logic error: cannot change query state from IDLE to PENDING
token.c:539:tds_process_tokens(0x180cf160, 0x7fff7aca9a1c, 0x7fff7aca9a18, 0x104)
token.c:542:tds_process_tokens() state is COMPLETED
odbc.c:1000:SQLNumParams(0x180d90e0, 0x7fff7aca9c1e)
odbc.c:1434:SQLBindParameter(0x180d90e0, 1, 1, 4, 4, 0, 0, 0x180cf9b8, 8, (nil))
odbc.c:1335:_SQLBindParameter(0x180d90e0, 1, 1, 4, 4, 0, 0, 0x180cf9b8, 8, (nil))
odbc.c:3501:SQLExecute(0x180d90e0)
prepare_query.c:203:parsing 0 parameters
sql2tds.c:190:type=4
sql2tds.c:198:trace
odbc.c:3216:_SQLExecute(0x180d90e0)
odbc.c:3221:_SQLExecute() starting with state 0
odbc.c:3339:End prepare, execute
query.c:1817:tds_submit_execute()
mem.c:615:tds_free_all_results()
util.c:156:Changed query state from IDLE to QUERYING
query.c:1470:tds_put_data_info putting status
query.c:1516:HERE!
query.c:1571:tds_put_data: colsize = 4
util.c:156:Changed query state from QUERYING to PENDING
net.c:730:Sending packet
0000 0f 01 00 2e 00 00 00 00-e7 0f 00 02 01 0a 79 38 |........ ......y8|
0010 72 6d 38 39 36 30 30 30-00 00 ec 0b 00 01 00 00 |rm896000 ........|
0020 00 00 00 00 00 26 04 00-d7 04 01 00 00 00 |.....&.. ......|
token.c:539:tds_process_tokens(0x180cf160, 0x7fff7aca9a74, 0x7fff7aca9a70, 0x6914)
util.c:156:Changed query state from PENDING to READING
net.c:546:Received header
0000 04 01 00 84 00 00 00 00- |........|
net.c:600:Received packet
0000 04 01 00 84 00 00 00 00-e7 0d 00 20 00 0a 79 38 |........ ... ..y8|
0010 72 6d 38 39 36 30 30 30-61 45 00 00 00 02 00 00 |rm896000 aE......|
0020 06 74 65 6d 70 64 62 03-64 62 6f 06 74 65 73 74 |.tempdb. dbo.test|
0030 65 72 02 69 64 10 00 00-00 07 00 00 00 38 00 00 |er.id... .....8..|
0040 06 74 65 6d 70 64 62 03-64 62 6f 06 74 65 73 74 |.tempdb. dbo.test|
0050 65 72 04 6e 61 6d 65 10-00 00 00 02 00 00 00 27 |er.name. .......'|
0060 14 00 ae 02 00 00 00 d1-01 00 00 00 05 74 65 73 |........ .....tes|
0070 74 31 ff 55 00 01 00 01-00 00 00 fe 0c 00 01 00 |t1.U.... ........|
0080 01 00 00 00 - |....|
token.c:554:processing result tokens. marker is e7(TDS5_DYNAMIC)
token.c:554:processing result tokens. marker is 61(ROWFMT2)
token.c:1831:tds5_process_result
mem.c:615:tds_free_all_results()
token.c:1855:num_cols=2
token.c:1958:col 0:
token.c:1959: column_name=[id]
token.c:1965: flags=10 utype=7 type=56 varint=0
token.c:1968: colsize=4 prec=0 scale=0
token.c:1958:col 1:
token.c:1959: column_name=[name]
token.c:1965: flags=10 utype=2 type=39 varint=1
token.c:1968: colsize=20 prec=0 scale=0
util.c:156:Changed query state from READING to PENDING
odbc.c:3539:odbc_process_tokens: tds_process_tokens returned 1
odbc.c:3540: result_type=4049, TDS_DONE_COUNT=0, TDS_DONE_ERROR=2
odbc.c:3610:odbc_process_tokens: returning result_type 4049
odbc.c:3379:_SQLExecute: odbc_process_tokens returned result_type 4049
token.c:539:tds_process_tokens(0x180cf160, 0x7fff7aca9a74, 0x7fff7aca9a70, 0x6914)
util.c:156:Changed query state from PENDING to READING
token.c:554:processing result tokens. marker is ae(CONTROL)
token.c:122:tds_process_default_tokens() marker is ae(CONTROL)
token.c:237:Eating CONTROL token
token.c:554:processing result tokens. marker is d1(ROW)
token.c:665:tds_process_tokens::SET_RETURN stopping on current token
util.c:156:Changed query state from READING to PENDING
odbc.c:3539:odbc_process_tokens: tds_process_tokens returned 1
odbc.c:3540: result_type=4040, TDS_DONE_COUNT=0, TDS_DONE_ERROR=2
odbc.c:3610:odbc_process_tokens: returning result_type 4040
odbc.c:3379:_SQLExecute: odbc_process_tokens returned result_type 4040
odbc.c:3524:SQLExecute returns SQL_SUCCESS
odbc.c:4159:SQLFreeStmt(0x180d90e0, 3)
odbc.c:4080:_SQLFreeStmt(0x180d90e0, 3, 0)
odbc.c:4500:_SQLRowCount(0x180d90e0, 0x7fff7aca9c80)
odbc.c:4519:SQLRowCount returns 0, row count -1
odbc.c:4414:SQLNumResultCols(0x180d90e0, 0x7fff7aca9c9e)
prepare_query.c:203:parsing 0 parameters
prepare_query.c:208:parse_prepared_query: logic_error: parameter out of bounds: 1 > 0 || 1 > 0
error.c:517:SQLGetDiagRec(3, 0x180d90e0, 1, 0x7fff7aca9bf0, 0x7fff7aca9c08, 0x7fff7aca97f0, 1023, 0x7fff7aca9c0e)
odbc.c:4159:SQLFreeStmt(0x180d90e0, 0)
odbc.c:4080:_SQLFreeStmt(0x180d90e0, 0, 0)
query.c:2138:tds_send_cancel: not in_cancel and not idle
query.c:2147:tds_send_cancel: sending cancel packet
net.c:730:Sending packet
0000 06 01 00 08 00 00 00 00- |........|
token.c:539:tds_process_tokens(0x180cf160, 0x7fff7aca9b14, (nil), 0x0)
util.c:156:Changed query state from PENDING to READING
token.c:554:processing result tokens. marker is d1(ROW)
token.c:2426:tds_process_row(): reading column 0
token.c:2171:tds_get_data: type 56, varint size 0
token.c:2232:tds_get_data(): wire column size is 4
token.c:2426:tds_process_row(): reading column 1
token.c:2171:tds_get_data: type 39, varint size 1
token.c:2232:tds_get_data(): wire column size is 5
token.c:554:processing result tokens. marker is ff(DONEINPROC)
token.c:2461:tds_process_end: more_results = 1
was_cancelled = 0
error = 0
done_count_valid = 1
token.c:2492: rows_affected = 1
token.c:554:processing result tokens. marker is fe(DONEPROC)
token.c:2461:tds_process_end: more_results = 0
was_cancelled = 0
error = 0
done_count_valid = 0
token.c:2492: rows_affected = 1
net.c:546:Received header
0000 04 01 00 11 00 00 00 00- |........|
net.c:600:Received packet
0000 04 01 00 11 00 00 00 00-fd 24 00 01 00 01 00 00 |........ .$......|
0010 00 - |.|
token.c:554:processing result tokens. marker is fd(DONE)
token.c:2461:tds_process_end: more_results = 0
was_cancelled = 1
error = 0
done_count_valid = 0
token.c:2477:tds_process_end() state set to TDS_IDLE
util.c:156:Changed query state from READING to IDLE
token.c:2492: rows_affected = 1
odbc.c:3985:SQLFreeHandle(3, 0x180d90e0)
odbc.c:4080:_SQLFreeStmt(0x180d90e0, 1, 0)
query.c:1918:tds_submit_unprepare() y8rm896000
mem.c:615:tds_free_all_results()
util.c:156:Changed query state from IDLE to QUERYING
util.c:156:Changed query state from QUERYING to PENDING
net.c:730:Sending packet
0000 0f 01 00 1a 00 00 00 00-e7 0f 00 04 00 0a 79 38 |........ ......y8|
0010 72 6d 38 39 36 30 30 30-00 00 |rm896000 ..|
token.c:539:tds_process_tokens(0x180cf160, 0x7fff7aca9bec, 0x7fff7aca9be8, 0x100)
util.c:156:Changed query state from PENDING to READING
net.c:546:Received header
0000 04 01 00 21 00 00 00 00- |...!....|
net.c:600:Received packet
0000 04 01 00 21 00 00 00 00-e7 0d 00 20 00 0a 79 38 |...!.... ... ..y8|
0010 72 6d 38 39 36 30 30 30-fd 04 00 01 00 00 00 00 |rm896000 ........|
0020 00 - |.|
token.c:554:processing result tokens. marker is e7(TDS5_DYNAMIC)
token.c:554:processing result tokens. marker is fd(DONE)
token.c:2461:tds_process_end: more_results = 0
was_cancelled = 0
error = 0
done_count_valid = 0
token.c:2477:tds_process_end() state set to TDS_IDLE
util.c:156:Changed query state from READING to IDLE
token.c:2492: rows_affected = 0
util.c:104:logic error: cannot change query state from IDLE to PENDING
token.c:539:tds_process_tokens(0x180cf160, 0x7fff7aca9bec, 0x7fff7aca9be8, 0x100)
token.c:542:tds_process_tokens() state is COMPLETED
odbc.c:4632:SQLEndTran(2, 0x180cd770, 1)
odbc.c:4610:_SQLTransact((nil), 0x180cd770, 1)
odbc.c:4571:change_transaction(0x0x180cd770,0)
mem.c:615:tds_free_all_results()
util.c:156:Changed query state from IDLE to QUERYING
util.c:156:Changed query state from QUERYING to PENDING
net.c:730:Sending packet
0000 0f 01 00 3b 00 00 00 00-21 2e 00 00 00 00 49 46 |...;.... !.....IF|
0010 20 40 40 54 52 41 4e 43-4f 55 4e 54 20 3e 20 30 | @@TRANC OUNT > 0|
0020 20 52 4f 4c 4c 42 41 43-4b 20 42 45 47 49 4e 20 | ROLLBAC K BEGIN |
0030 54 52 41 4e 53 41 43 54-49 4f 4e |TRANSACT ION|
token.c:539:tds_process_tokens(0x180cf160, 0x7fff7aca9c7c, 0x7fff7aca9c78, 0x100)
util.c:156:Changed query state from PENDING to READING
net.c:546:Received header
0000 04 01 00 23 00 00 00 00- |...#....|
net.c:600:Received packet
0000 04 01 00 23 00 00 00 00-fd 05 00 01 00 00 00 00 |...#.... ........|
0010 00 fd 01 00 03 00 00 00-00 00 fd 04 00 01 00 00 |........ ........|
0020 00 00 00 - |...|
token.c:554:processing result tokens. marker is fd(DONE)
token.c:2461:tds_process_end: more_results = 1
was_cancelled = 0
error = 0
done_count_valid = 0
token.c:2492: rows_affected = 0
util.c:156:Changed query state from READING to PENDING
token.c:539:tds_process_tokens(0x180cf160, 0x7fff7aca9c7c, 0x7fff7aca9c78, 0x100)
util.c:156:Changed query state from PENDING to READING
token.c:554:processing result tokens. marker is fd(DONE)
token.c:2461:tds_process_end: more_results = 1
was_cancelled = 0
error = 0
done_count_valid = 0
token.c:2492: rows_affected = 0
util.c:156:Changed query state from READING to PENDING
token.c:539:tds_process_tokens(0x180cf160, 0x7fff7aca9c7c, 0x7fff7aca9c78, 0x100)
util.c:156:Changed query state from PENDING to READING
token.c:554:processing result tokens. marker is fd(DONE)
token.c:2461:tds_process_end: more_results = 0
was_cancelled = 0
error = 0
done_count_valid = 0
token.c:2477:tds_process_end() state set to TDS_IDLE
util.c:156:Changed query state from READING to IDLE
token.c:2492: rows_affected = 0
util.c:104:logic error: cannot change query state from IDLE to PENDING
token.c:539:tds_process_tokens(0x180cf160, 0x7fff7aca9c7c, 0x7fff7aca9c78, 0x100)
token.c:542:tds_process_tokens() state is COMPLETED
odbc.c:5815:SQLGetInfo(0x180cd770, 23, 0x180b8100, 2, 0x7fff7aca9dce)
odbc.c:5069:_SQLGetInfo(0x180cd770, 23, 0x180b8100, 2, 0x7fff7aca9dce
odbc.c:5815:SQLGetInfo(0x180cd770, 24, 0x180b8102, 2, 0x7fff7aca9dce)
odbc.c:5069:_SQLGetInfo(0x180cd770, 24, 0x180b8102, 2, 0x7fff7aca9dce
odbc.c:2237:SQLDisconnect(0x180cd770)
odbc.c:4080:_SQLFreeStmt(0x180cd5c0, 1, 1)
mem.c:615:tds_free_all_results()
util.c:156:Changed query state from IDLE to DEAD
odbc.c:3985:SQLFreeHandle(2, 0x180cd770)
odbc.c:4011:_SQLFreeConnect(0x180cd770)
odbc.c:3985:SQLFreeHandle(1, 0x180cc0b0)
odbc.c:4055:_SQLFreeEnv(0x180cc0b0)
-Peter
On Tue, Oct 19, 2010 at 06:29:00PM +0200, Frediano Ziglio wrote:
> A debugger is not nevessary. In this case a DM (unixODBC in your case)
> trace would be ok. A FreeTDS dump is also ok.
>
> Regards
> Frediano
>
> Il giorno mar, 19/10/2010 alle 11.42 -0400, Peter C. Norton ha scritto:
> > It looks like the sybase server will return something other than
> > SQL_SUCCESS, then. This is against the following Sybase ASE:
> >
> > Adaptive Server Enterprise/15.0.3/EBF 17166 ESD#3/P/Solaris AMD64/OS 5.10/ase1503/2726/64-bit/FBO/Fri Feb 5 02:16:02 2010
> >
> > Would a dump/trace of the tds session contain an indication of the
> > return value, or do I need to re-enable this code and attach with a
> > debugger?
> >
> > -Peter
> >
> > On Tue, Oct 19, 2010 at 09:08:10AM +0200, Frediano Ziglio wrote:
> > > The patch add lazy prepare which improve performance and works better
> > > with DBD::ODBC.
> > > If I understood correctly using mssql works correct but with Sybase
> > > server the results is not ok. Am I right?
> > > The correct solution is fix the issue using Sybase.
> > >
> > > freddy77
> > >
> > > 2010/10/15 Peter C. Norton <[email protected]>:
> > > > Hi, I've got another bug report. ??At my site we've run into a
> > > > regression when going from the following:
> > > >
> > > > pyodbc-2.1.7
> > > > ??depends on
> > > > unixODBC-2.2.14
> > > > ??which depends on
> > > > freetds-0.82.1.dev.20091223
> > > >
> > > > to the same pyodbc and unixODBC, but upgrading to
> > > > freetds-0.83.dev.20100902 + various patches from upstream. ??When users
> > > > tested it I got the following succinct bug report:
> > > >
> > > > import pyodbc
> > > > def the_test(db_name):
> > > > ?? ??db = pyodbc.connect("DSN=%s;UID=<USERNAME>;PWD=<PASSWORD>;DATABASE=<any database>;APP=python_test" % db_name)
> > > > ?? ??q = db.execute("select * from <any table> where type = ?", (1,))
> > > > ?? ??print q.fetchall()
> > > >
> > > > the_test("SYBASE")
> > > >
> > > > results in the following error:
> > > >
> > > > Error: ('HY000', 'The driver did not supply an error!')
> > > >
> > > > Confirmed on solaris x86 and linux/64-bit. ??I've bisected the changes
> > > > made back to 5/19/2010 via the freetds git repository and I found that
> > > > the following broke prepared statements from pyodbc:
> > > >
> > > > http://github.com/brianb/FreeTDS/commit/2ed78ea4dd9018927b56822e318e0b5ac9401b98#diff-2
> > > >
> > > > Specifically the chunk between line 1301 and 1313. The relevent chunk of code is this:
> > > >
> > > > ?? ?? ?? ?? ?? ?? ?? ??if (desc->type == DESC_IRD && ((TDS_STMT*)desc->parent)->need_reprepare && \
> > > > ?? ?? ?? ?? ?? ?? ?? ?? ?? ??odbc_update_ird((TDS_STMT*)desc->parent, errs) != SQL_SUCCESS) \
> > > > ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ?? ??exit; \
> > > >
> > > > Reverting the patch to the pre-2010-05-19 state has the preprocessor
> > > > replace the above with:
> > > >
> > > > #define IRD_UPDATE(desc, errs, exit) do { } while(0)
> > > >
> > > > which may just be masking an error, but I do not know. ??Backing this
> > > > out causes prepared statements to work again. ??Are there any gotchas
> > > > to reverting this change? ??And is there a better/more correct fix for
> > > > this?
> > > >
> > > > By the way, this works fine when I point the same test an an MSSQL 2005 or 2008 server.
> > > >
> > > > Thanks,
> > > >
> > > > -Peter
> > > >
> > > _______________________________________________
> > > FreeTDS mailing list
> > > [email protected]
> > > http://lists.ibiblio.org/mailman/listinfo/freetds
> > _______________________________________________
> > FreeTDS mailing list
> > [email protected]
> > http://lists.ibiblio.org/mailman/listinfo/freetds
>
>
> _______________________________________________
> FreeTDS mailing list
> [email protected]
> http://lists.ibiblio.org/mailman/listinfo/freetds