Re: [re-sending: Another freetds + unixODBC + pyodbc issue]
Frediano Ziglio <[email protected]>
| Newsgroups | gmane.comp.db.tds.freetds |
|---|---|
| Message-ID | <[email protected]> |
Hi, could you try this patch. I rewrote odbc_stat_execute using RPC instead of building the string. Frediano Ziglio 2010/11/24 Peter C. Norton <[email protected]>: > I'm re-sending this to the list because it's the one outstanding issue > that I'm aware of at this time with freetds. I think it's gotten lost > in the glut of error reports I sent earlier. > > I've confirmed that this still exists based on a checkout from the > most recent available snapshot (cvs->git mirror->me, last changelog is > updated as of 10/29. Brianb, is your git sync script still working?) > > Let me know if more info is needed. > > Thanks, > > -Peter > > > ----- Forwarded message from "Peter C. Norton" ----- > > Sorry for the length of this post. I'm trying to become familiar with > what's going on here so I'm putting in perhaps too much information > rather than too little. > > It seems like when I'm connecting to a Sybase server (belonging to a > vendor, which I have no control over), I will reliably get an error > message when issuing something as simple as "select 1". This seems to > be the same issue as another users pyodbc issue #89, at > http://code.google.com/p/pyodbc/issues/detail?id=89. I'm sending this > here, because so far my debugging seems to point to freetds's odbc.c, > but I could be wrong. > > When this issue happens, this is what the top of the call stack looks like: > > #0 _SQLExecute (stmt=0x8309e0) at odbc.c:3224 > #1 0x00002aaaae77afed in SQLExecDirect (statement_handle=0x831870, statement_text=0x2aaaaaf656b4 "select 1", text_length=-3) at SQLExecDirect.c:421 > #2 0x00002aaaae555dab in execute (cur=0x6fd030, pSql=0x2aaaaaf65690, params=0x0, skip_first=false) at /var/tmp/pyodbc/src/cursor.cpp:673 > #3 0x00002aaaaab998bd in call_function (f=0x7899a0, throwflag=<value optimized out>) at Python/ceval.c:3750 > > I've attached the relevant section of the dump file, starting at 4635 > lines into the output. > > The part that seems to be generating the error seems to be the state > machine left in the "wrong" state, with more_results being set, and > the state being set to TDS_PENDING (below, in gdb), but that's not > valid after the SQLFetch: NO_DATA_FOUND? > > util.c:156:Changed query state from PENDING to READING > 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 > util.c:156:Changed query state from READING to PENDING > odbc.c:3534:odbc_process_tokens: tds_process_tokens returned 1 > odbc.c:3535: result_type=4054, TDS_DONE_COUNT=10, TDS_DONE_ERROR=0 > odbc.c:3599:odbc_process_tokens: processed TDS_DONEINPROC_RESULT > odbc.c:3803:SQLFetch: NO_DATA_FOUND > odbc.c:5940:SQLGetTypeInfo(0x84ccc00, -2) > odbc.c:3211:_SQLExecute(0x84ccc00) > odbc.c:3216:_SQLExecute() starting with state 2 > error.c:412:odbc_errs_add: "Invalid cursor state" > > and all this seems to happen before the "select 1" is ever passed to the server. > > I can verify, at least, that from the debuggers point of view, the > state seems to be consistent with the error conditions being checked > for. Going into odbc.c:_SQLExecute when the above happens, this is > what the struct *tds looks like (from another run, btw, so the memory > addresses probably don't match): > > (gdb) p *tds > $44 = {s = 6, tds_version = 1280, product_version = 201654272, product_name = 0x829b80 "sql server", capabilities = "\001\t\000\b\002aA????\002\t\000\000\000\000\002\000\000\000", broken_dates = 0, emul_little_endian = 0, use_iconv = 0, in_buf = 0x82a310 "\004\001\001J", out_buf = 0x829360 "\017\001", in_buf_max = 512, in_pos = 316, out_pos = 8, in_len = 330, in_flag = 4 '\004', out_flag = 15 '\017', parent = 0x826010, current_results = 0x827cd0, res_info = 0x827cd0, num_comp_info = 0, comp_info = 0x0, param_info = 0x0, cur_cursor = 0x0, cursors = 0x0, has_status = 0 '\000', ret_status = 0, state = TDS_PENDING, in_cancel = 0 '\000', rows_affected = 1, query_timeout = 0, env = {block_size = 512, language = 0x0, charset = 0x827d60 "iso_1", database = 0x829aa0 "tempdb"}, cur_dyn = 0x0, dyns = 0x0, tds_ctx = 0x827ca0, char_conv_count = 4, char_convs = 0x827d30, connection = 0x0, spid = -1, collation = "\000\000\000\000", tds9_transaction = "\000\000\000\000\000\000\000", env_ > chg_func = 0x2aaab1a7f2a0 <odbc_env_change>, internal_sp_called = 0, tls_session = 0x0, tls_credentials = 0x0, authentication = 0x0, option_value = 0} > (gdb) > > > this is the state of the *tds structure when this code in odbc.c is hit: > > (gdb) list > 3219 if (stmt->params && stmt->param_num <= stmt->param_count) > 3220 /* TODO what error ?? */ > 3221 return SQL_ERROR; > 3222 > 3223 if (tds->state != TDS_IDLE) { > 3224 if (tds->state == TDS_DEAD) { > 3225 odbc_errs_add(&stmt->errs, "08S01", NULL); > 3226 } else { > 3227 odbc_errs_add(&stmt->errs, "24000", NULL); > 3228 } > > The sequence of odbc discovery queryes via "EXEC sp_datatypeinfo %d" > requests leading up to this, via putting a breakpoint in > osbc.c:_SQLExecute(), looks like this: > > EXEC sp_datatype_info 11 > EXEC sp_datatype_info 12 > EXEC sp_datatype_info 12 > EXEC sp_datatype_info -9 > EXEC sp_datatype_info -2 > > Then after this, the next time _SQLExecute is entered, it's trying to > execute "select 1", and per the attached dump, it fails miserably > because the connection is in an invalid state. > > An interesting note: it seems like on this database 11, 12, and -2 > return multiple types that have the matching data_type. -9 doesn't > match anything. > > Could it be that something about the multiple values being returned by > sp_datatype_info are the cause of the problem here? > > From looking at odbc.c:SQLGetTypeInfo(), it looks like where it's > checking for the types (starting at line 5890 in my current checkout) > something may be going wrong. I see that on this dataserver > "sp_datatype_info -2" returns 4 rows, and the first one is the > definition of "binary" and the rest are defined by someone else > (probably the vendor who owns the box). Looking at SQLGetTypeInfo(): > > /* > * Sybase return first nvarchar for char... and without length !!! > * Some program use first entry so we discard all entry bfore varchar > */ > n = 0; > while (tds->current_results) { > TDSRESULTINFO *resinfo; > TDSCOLUMN *colinfo; > char *name; > > /* if next is varchar leave next for SQLFetch */ > if (n == (varchar_pos - 1)) > break; > > switch (tds_process_tokens(stmt->dbc->tds_socket, &result_type, &compute_id, TDS_STOPAT_ROWFMT|TDS_RETURN_ROW)) { > case TDS_SUCCEED: > if (result_type == TDS_ROW_RESULT) > break; > case TDS_NO_MORE_RESULTS: > /* discard other tokens */ > tds_process_simple_query(tds); > if (n >= varchar_pos && varchar_pos > 0) > goto redo; > break; > case TDS_CANCELLED: > odbc_errs_add(&stmt->errs, "HY008", NULL); > break; > } > if (!tds->current_results) > break; > ++n; > > resinfo = tds->current_results; > colinfo = resinfo->columns[0]; > name = (char *) colinfo->column_data; > /* skip nvarchar and sysname */ > if (colinfo->column_cur_size == 7 && memcmp("varchar", name, 7) == 0) { > varchar_pos = n; > } > } > ODBC_RETURN(stmt, res); > > when ODBC_RETURN returns, the value returned to the caller is -1 after > the call to "EXEC sp_datatype_info -2". > > Let me know if I can provide more info, or help narrow down what the > exact problem is here. > > Thanks, > > -Peter > > > > > net.c:730:Sending packet > 0000 0f 01 00 26 00 00 00 00-21 19 00 00 00 00 45 58 |...&.... !.....EX| > 0010 45 43 20 73 70 5f 64 61-74 61 74 79 70 65 5f 69 |EC sp_da tatype_i| > 0020 6e 66 6f 20 2d 39 - |nfo -9| > > token.c:539:tds_process_tokens(0x84ce7e0, 0x7fff9a296ba4, 0x7fff9a296ba0, 0x6914) > util.c:156:Changed query state from PENDING to READING > net.c:546:Received header > 0000 04 00 02 00 00 00 00 00- |........| > > net.c:600:Received packet > 0000 04 00 02 00 00 00 00 00-ff 45 00 01 00 00 00 00 |........ .E......| > 0010 00 61 f8 02 00 00 11 00-09 74 79 70 65 5f 6e 61 |.a...... .type_na| > 0020 6d 65 00 00 08 73 79 73-74 79 70 65 73 04 6e 61 |me...sys types.na| > 0030 6d 65 10 00 00 00 12 00-00 00 27 1e 00 00 00 00 |me...... ..'.....| > 0040 11 73 70 74 5f 64 61 74-61 74 79 70 65 5f 69 6e |.spt_dat atype_in| > 0050 66 6f 09 64 61 74 61 5f-74 79 70 65 10 00 00 00 |fo.data_ type....| > 0060 06 00 00 00 34 00 08 70-72 65 63 69 73 6f 6e 00 |....4..p recison.| > 0070 00 00 08 70 72 65 63 69-73 6f 6e 30 00 00 00 07 |...preci son0....| > 0080 00 00 00 26 04 00 00 00-00 11 73 70 74 5f 64 61 |...&.... ..spt_da| > 0090 74 61 74 79 70 65 5f 69-6e 66 6f 0e 6c 69 74 65 |tatype_i nfo.lite| > 00a0 72 61 6c 5f 70 72 65 66-69 78 30 00 00 00 02 00 |ral_pref ix0.....| > 00b0 00 00 27 20 00 00 00 00-11 73 70 74 5f 64 61 74 |..' .... .spt_dat| > 00c0 61 74 79 70 65 5f 69 6e-66 6f 0e 6c 69 74 65 72 |atype_in fo.liter| > 00d0 61 6c 5f 73 75 66 66 69-78 30 00 00 00 02 00 00 |al_suffi x0......| > 00e0 00 27 20 00 00 00 00 15-73 70 74 5f 64 61 74 61 |.' ..... spt_data| > 00f0 74 79 70 65 5f 69 6e 66-6f 5f 65 78 74 0d 63 72 |type_inf o_ext.cr| > 0100 65 61 74 65 5f 70 61 72-61 6d 73 30 00 00 00 02 |eate_par ams0....| > 0110 00 00 00 27 20 00 00 00-00 11 73 70 74 5f 64 61 |...' ... ..spt_da| > 0120 74 61 74 79 70 65 5f 69-6e 66 6f 08 6e 75 6c 6c |tatype_i nfo.null| > 0130 61 62 6c 65 10 00 00 00-06 00 00 00 34 00 00 00 |able.... ....4...| > 0140 00 11 73 70 74 5f 64 61-74 61 74 79 70 65 5f 69 |..spt_da tatype_i| > 0150 6e 66 6f 0e 63 61 73 65-5f 73 65 6e 73 69 74 69 |nfo.case _sensiti| > 0160 76 65 10 00 00 00 06 00-00 00 34 00 00 00 00 11 |ve...... ..4.....| > 0170 73 70 74 5f 64 61 74 61-74 79 70 65 5f 69 6e 66 |spt_data type_inf| > 0180 6f 0a 73 65 61 72 63 68-61 62 6c 65 10 00 00 00 |o.search able....| > 0190 06 00 00 00 34 00 00 00-00 11 73 70 74 5f 64 61 |....4... ..spt_da| > 01a0 74 61 74 79 70 65 5f 69-6e 66 6f 12 75 6e 73 69 |tatype_i nfo.unsi| > 01b0 67 6e 65 64 5f 61 74 74-72 69 62 75 74 65 30 00 |gned_att ribute0.| > 01c0 00 00 06 00 00 00 26 02-00 00 00 00 11 73 70 74 |......&. .....spt| > 01d0 5f 64 61 74 61 74 79 70-65 5f 69 6e 66 6f 05 6d |_datatyp e_info.m| > 01e0 6f 6e 65 79 10 00 00 00-06 00 00 00 34 00 00 00 |oney.... ....4...| > 01f0 00 11 73 70 74 5f 64 61-74 61 74 79 70 65 5f 69 |..spt_da tatype_i| > > 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 = 0 > token.c:2492: rows_affected = 0 > util.c:156:Changed query state from READING to PENDING > odbc.c:3534:odbc_process_tokens: tds_process_tokens returned 1 > odbc.c:3535: result_type=4054, TDS_DONE_COUNT=0, TDS_DONE_ERROR=0 > odbc.c:3599:odbc_process_tokens: processed TDS_DONEINPROC_RESULT > odbc.c:3374:_SQLExecute: odbc_process_tokens returned result_type 4054 > token.c:539:tds_process_tokens(0x84ce7e0, 0x7fff9a296ba4, 0x7fff9a296ba0, 0x6914) > util.c:156:Changed query state from PENDING to READING > 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=17 > token.c:1958:col 0: > token.c:1959: column_name=[type_name] > token.c:1965: flags=10 utype=18 type=39 varint=1 > token.c:1968: colsize=30 prec=0 scale=0 > token.c:1958:col 1: > token.c:1959: column_name=[data_type] > token.c:1965: flags=10 utype=6 type=52 varint=0 > token.c:1968: colsize=2 prec=0 scale=0 > token.c:1958:col 2: > token.c:1959: column_name=[precison] > token.c:1965: flags=30 utype=7 type=38 varint=1 > token.c:1968: colsize=4 prec=0 scale=0 > token.c:1958:col 3: > token.c:1959: column_name=[literal_prefix] > token.c:1965: flags=30 utype=2 type=39 varint=1 > token.c:1968: colsize=32 prec=0 scale=0 > token.c:1958:col 4: > token.c:1959: column_name=[literal_suffix] > token.c:1965: flags=30 utype=2 type=39 varint=1 > token.c:1968: colsize=32 prec=0 scale=0 > token.c:1958:col 5: > token.c:1959: column_name=[create_params] > token.c:1965: flags=30 utype=2 type=39 varint=1 > token.c:1968: colsize=32 prec=0 scale=0 > token.c:1958:col 6: > token.c:1959: column_name=[nullable] > token.c:1965: flags=10 utype=6 type=52 varint=0 > token.c:1968: colsize=2 prec=0 scale=0 > token.c:1958:col 7: > token.c:1959: column_name=[case_sensitive] > token.c:1965: flags=10 utype=6 type=52 varint=0 > token.c:1968: colsize=2 prec=0 scale=0 > token.c:1958:col 8: > token.c:1959: column_name=[searchable] > token.c:1965: flags=10 utype=6 type=52 varint=0 > token.c:1968: colsize=2 prec=0 scale=0 > token.c:1958:col 9: > token.c:1959: column_name=[unsigned_attribute] > token.c:1965: flags=30 utype=6 type=38 varint=1 > token.c:1968: colsize=2 prec=0 scale=0 > token.c:1958:col 10: > token.c:1959: column_name=[money] > token.c:1965: flags=10 utype=6 type=52 varint=0 > token.c:1968: colsize=2 prec=0 scale=0 > net.c:546:Received header > 0000 04 01 01 4a 00 00 00 00- |...J....| > > net.c:600:Received packet > 0000 04 01 01 4a 00 00 00 00-6e 66 6f 0e 61 75 74 6f |...J.... nfo.auto| > 0010 5f 69 6e 63 72 65 6d 65-6e 74 30 00 00 00 06 00 |_increme nt0.....| > 0020 00 00 26 02 00 00 00 00-11 73 70 74 5f 64 61 74 |..&..... .spt_dat| > 0030 61 74 79 70 65 5f 69 6e-66 6f 0f 6c 6f 63 61 6c |atype_in fo.local| > 0040 5f 74 79 70 65 5f 6e 61-6d 65 10 00 00 00 02 00 |_type_na me......| > 0050 00 00 27 80 00 00 00 00-11 73 70 74 5f 64 61 74 |..'..... .spt_dat| > 0060 61 74 79 70 65 5f 69 6e-66 6f 0d 73 71 6c 5f 64 |atype_in fo.sql_d| > 0070 61 74 61 5f 74 79 70 65-30 00 00 00 06 00 00 00 |ata_type 0.......| > 0080 26 02 00 00 00 00 11 73-70 74 5f 64 61 74 61 74 |&......s pt_datat| > 0090 79 70 65 5f 69 6e 66 6f-10 73 71 6c 5f 64 61 74 |ype_info .sql_dat| > 00a0 65 74 69 6d 65 5f 73 75-62 30 00 00 00 06 00 00 |etime_su b0......| > 00b0 00 26 02 00 00 00 00 11-73 70 74 5f 64 61 74 61 |.&...... spt_data| > 00c0 74 79 70 65 5f 69 6e 66-6f 0e 6e 75 6d 5f 70 72 |type_inf o.num_pr| > 00d0 65 63 5f 72 61 64 69 78-30 00 00 00 06 00 00 00 |ec_radix 0.......| > 00e0 26 02 00 00 00 00 11 73-70 74 5f 64 61 74 61 74 |&......s pt_datat| > 00f0 79 70 65 5f 69 6e 66 6f-12 69 6e 74 65 72 76 61 |ype_info .interva| > 0100 6c 5f 70 72 65 63 69 73-69 6f 6e 30 00 00 00 06 |l_precis ion0....| > 0110 00 00 00 26 02 00 ae 11-00 00 00 00 00 00 00 00 |...&.... ........| > 0120 00 00 00 00 00 00 00 00-00 00 ff 55 00 01 00 00 |........ ...U....| > 0130 00 00 00 ff 55 00 01 00-01 00 00 00 79 00 00 00 |....U... ....y...| > 0140 00 fe 0c 00 01 00 01 00-00 00 |........ ..| > > token.c:1958:col 11: > token.c:1959: column_name=[auto_increment] > token.c:1965: flags=30 utype=6 type=38 varint=1 > token.c:1968: colsize=2 prec=0 scale=0 > token.c:1958:col 12: > token.c:1959: column_name=[local_type_name] > token.c:1965: flags=10 utype=2 type=39 varint=1 > token.c:1968: colsize=128 prec=0 scale=0 > token.c:1958:col 13: > token.c:1959: column_name=[sql_data_type] > token.c:1965: flags=30 utype=6 type=38 varint=1 > token.c:1968: colsize=2 prec=0 scale=0 > token.c:1958:col 14: > token.c:1959: column_name=[sql_datetime_sub] > token.c:1965: flags=30 utype=6 type=38 varint=1 > token.c:1968: colsize=2 prec=0 scale=0 > token.c:1958:col 15: > token.c:1959: column_name=[num_prec_radix] > token.c:1965: flags=30 utype=6 type=38 varint=1 > token.c:1968: colsize=2 prec=0 scale=0 > token.c:1958:col 16: > token.c:1959: column_name=[interval_precision] > token.c:1965: flags=30 utype=6 type=38 varint=1 > token.c:1968: colsize=2 prec=0 scale=0 > util.c:156:Changed query state from READING to PENDING > odbc.c:3534:odbc_process_tokens: tds_process_tokens returned 1 > odbc.c:3535: result_type=4049, TDS_DONE_COUNT=0, TDS_DONE_ERROR=0 > odbc.c:3605:odbc_process_tokens: returning result_type 4049 > odbc.c:3374:_SQLExecute: odbc_process_tokens returned result_type 4049 > token.c:539:tds_process_tokens(0x84ce7e0, 0x7fff9a296ba4, 0x7fff9a296ba0, 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 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 = 0 > util.c:156:Changed query state from READING to PENDING > odbc.c:3534:odbc_process_tokens: tds_process_tokens returned 1 > odbc.c:3535: result_type=4054, TDS_DONE_COUNT=10, TDS_DONE_ERROR=0 > odbc.c:3599:odbc_process_tokens: processed TDS_DONEINPROC_RESULT > odbc.c:3374:_SQLExecute: odbc_process_tokens returned result_type 4054 > odbc.c:3935:SQLFetch(0x84ccc00) > odbc.c:3671:_SQLFetch(0x84ccc00, 1, 0) > token.c:539:tds_process_tokens(0x84ce7e0, 0x7fff9a296b74, 0x7fff9a296b70, 0x6508) > util.c:156:Changed query state from PENDING to READING > 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 > util.c:156:Changed query state from READING to PENDING > odbc.c:3534:odbc_process_tokens: tds_process_tokens returned 1 > odbc.c:3535: result_type=4054, TDS_DONE_COUNT=10, TDS_DONE_ERROR=0 > odbc.c:3599:odbc_process_tokens: processed TDS_DONEINPROC_RESULT > odbc.c:3803:SQLFetch: NO_DATA_FOUND > odbc.c:5940:SQLGetTypeInfo(0x84ccc00, -2) > odbc.c:3211:_SQLExecute(0x84ccc00) > odbc.c:3216:_SQLExecute() starting with state 2 > error.c:412:odbc_errs_add: "Invalid cursor state" > error.c:517:SQLGetDiagRec(3, 0x84ccc00, 1, 0x7fff9a296c50, 0x7fff9a296c6c, 0x7fff9a296a50, 512, 0x7fff9a296c68) > error.c:566:SQLGetDiagRec: "[FreeTDS][SQL Server]Invalid cursor state" > error.c:517:SQLGetDiagRec(3, 0x84ccc00, 2, 0x7fff9a296c50, 0x7fff9a296c6c, 0x7fff9a296a50, 512, 0x7fff9a296c68) > odbc.c:1716:SQLAllocStmt(0x84ccda0, 0x84d7580) > odbc.c:1615:_SQLAllocStmt(0x84ccda0, 0x84d7580) > odbc.c:4154:SQLFreeStmt(0x84d6310, 0) > odbc.c:4075:_SQLFreeStmt(0x84d6310, 0, 0) > odbc.c:3463:SQLExecDirect(0x84d6310, 0x2b1610cc96b4, -3) > prepare_query.c:203:parsing 0 parameters > odbc.c:3211:_SQLExecute(0x84d6310) > odbc.c:3216:_SQLExecute() starting with state 2 > error.c:412:odbc_errs_add: "Invalid cursor state" > error.c:517:SQLGetDiagRec(3, 0x84d6310, 1, 0x7fff9a296d50, 0x7fff9a296d6c, 0x7fff9a296b50, 512, 0x7fff9a296d68) > error.c:566:SQLGetDiagRec: "[FreeTDS][SQL Server]Invalid cursor state" > error.c:517:SQLGetDiagRec(3, 0x84d6310, 2, 0x7fff9a296d50, 0x7fff9a296d6c, 0x7fff9a296b50, 512, 0x7fff9a296d68) > error.c:517:SQLGetDiagRec(3, 0x84d6310, 1, 0x7fff9a296e90, 0x7fff9a296ea8, 0x7fff9a296a90, 1023, 0x7fff9a296eae) > error.c:566:SQLGetDiagRec: "[FreeTDS][SQL Server]Invalid cursor state" > > > ----- End forwarded message ----- > _______________________________________________ > FreeTDS mailing list > [email protected] > http://lists.ibiblio.org/mailman/listinfo/freetds > _______________________________________________ FreeTDS mailing list [email protected] http://lists.ibiblio.org/mailman/listinfo/freetds
rpcstat.diff.gz
(application/x-gzip, 2.3 KB) - not displayed