FreeTDS Development Group

["Peter C. Norton" <spacey-freetds.org AT ssr.com>]

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