Re: Commit to odbc.c from 5/19/2010 breaks prepared statements with pyodbc
Frediano Ziglio <[email protected]>
| Newsgroups | gmane.comp.db.tds.freetds |
|---|---|
| Message-ID | <[email protected]> |
Just committed a patch. Added a peter.c test :) Sybase does not need to prepare again if binding change ... freddy77 2010/10/19 Peter C. Norton <[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 > _______________________________________________ > FreeTDS mailing list > [email protected] > http://lists.ibiblio.org/mailman/listinfo/freetds > _______________________________________________ FreeTDS mailing list [email protected] http://lists.ibiblio.org/mailman/listinfo/freetds