FreeTDS Development Group

[Fredy Paquet <fredy AT opag.ch>]

Hello

I need some help on this, brcause i can not completely figure out why
it's going wrong. 

Is there anyone around that fully understands how the tds protocol
parser works ? 

What might be the reason for returning cmd->results_state
_CS_RES_RESULTSET_ROWS in an empty rowset ? (see below)

fp

Steps to reproduce:
- roll back commit 4fea9e for testing purpose, is fixing the missing
ROWFMT message (actually very few changes, subject to discussion).

- the application is hanging in ct_fetch() -> tds_peek() ->
tds_get_byte()

(gdb) bt
#0  0x00007ffff3647e10 in __poll_nocancel () from /lib64/libc.so.6
#1  0x00007ffff461b016 in tds_select (tds=tds@entry=0xc567f0, 
    tds_sel=tds_sel@entry=1, timeout_seconds=<optimized out>) at
net.c:621
#2  0x00007ffff461f73a in tds_connection_network
(conn=conn@entry=0xc564b0, 
    tds=tds@entry=0xc567f0, send=send@entry=0) at packet.c:378
#3  0x00007ffff4620029 in tds_read_packet (tds=tds@entry=0xc567f0)
    at packet.c:578
#4  0x00007ffff4605db8 in tds_get_byte (tds=tds@entry=0xc567f0) at
read.c:75
#5  0x00007ffff4605df9 in tds_peek (tds=tds@entry=0xc567f0) at
read.c:102
#6  0x00007ffff45f0f50 in ct_fetch (cmd=0xc56a40, type=-99999,
offset=-99999, 
    option=-99999, prows_read=0xdbf068) at ct.c:1601
#7  0x0000000000452389 in sqlsybcs_nextrow (q=0xc55e70) at
sqlsybcs.c:1485

Analysis:

ct.c:1210:ct_results() process_result_tokens returned 0 (type 4052) 
ct.c:1316:ct_results() results state = 1
ct.c:1317:ct_results() command type  = 148
ct.c:1318:ct_results() dynamic cmd   = 0
ct.c:1340:_CS_RES_RESULTSET_EMPTY command_type 148
ct.c:2366:ct_res_info(0xc56a40, 803, 0xdbee2c, -99999, (nil))
ct.c:2385:ct_res_info(): Number of columns is 1
ct.c:2306:ct_describe(0xc56a40, 1, 0xdbec30)
ct.c:1904:_ct_get_client_type(type 52, user 6, size 2)
ct.c:2323:ct_describe() datafmt->datatype = 7 server type 52
ct.c:1487:ct_bind(0xc56a40, 1, 0xdbece0, 0xdd01c0, (nil), 0xca1400)
ct.c:1489:ct_bind() datafmt count = 1 column_number = 1
ct.c:1548:ct_fetch(0xc56a40, -99999, -99999, -99999, 0xdbf068)

ct.c:1210:ct_results() process_result_tokens returned 0 (type 4052) 
-> returned 0 means TDS_SUCCESS
-> type 4052 means res_type is TDS_DONE_RESULT

ct.c:1316:ct_results() results state = 1
-> state 1 means _CS_RES_RESULTSET_EMPTY

ct.c:1317:ct_results() command type  = 148
-> 148 is CS_LANG_CMD

If we look at lines following tdsdump_log() in ct.c:1210:ct_results()
for(;;)
...
  case TDS_SUCCESS
  ...
    case TDS_DONE_RESULT
    ...
      case _CS_RES_RESULTSET_EMPTY

we find that this cmd->result_state is always set to
_CS_RES_RESULTSET_ROWS which looked **suspicios** to us, with an empty
result set?

Ater changing the line 1348 in ct.c, as below, our application is no
longer hanging and running fine with lots of SQL processing.

case _CS_RES_RESULTSET_EMPTY:
  tdsdump_log(
    TDS_DBG_FUNC,
    "_CS_RES_RESULTSET_EMPTY command_type %d\n",
    cmd->command_type);

  if (cmd->command_type == CS_CUR_CMD) {
    *result_type = CS_CURSOR_RESULT;
  } else {
    *result_type = CS_ROW_RESULT;
  }
- cmd->results_state = _CS_RES_RESULTSET_ROWS;
+ cmd->results_state = _CS_RES_CMD_DONE;

With the above change, the problem seams to be solved.

fp

On Sat, 2017-07-08 at 17:03 +0200, Fredy Paquet wrote:
> Hello Frediano
> 
> Sorry to bother you again.
> 
> I'm testing FreeTDS 1.1 (current master branch) with our Sybase ASE 15.7
> ctLib application.
> 
> We found our application to crash after the first SELECT has been
> issued, returning result rows.
> 
> Attached there are two TDSDUMP files:
> 
> ctlib_ok.log - taken with FreeTDS 0.91
> ctlib_bad.log - taken with FreeTDS 1.1
> 
> If we look at the tds dump, we find that token.c is recognizing the
> ROWFMT2 result, but doesn't pass correct information back to ct_result()
> in ct.c (~Line 1215) to process CS_ROWFMT_RESULT. In ctlib_ok.log, you
> can find ct_res_info() calls after "process_result_tokens returned", but
> not in ctlib_bad.log.
> 
> ctlib_ok.log Line 452ff
> 
> token.c:555:processing result tokens.  marker is  61(ROWFMT2)
> token.c:1740:tds5_process_result
> mem.c:615:tds_free_all_results()
> token.c:1764:num_cols=2
> token.c:1837:col 0:
> token.c:1838: column_name=[name]
> token.c:1844: flags=10 utype=42 type=47 varint=5
> token.c:1847: colsize=510 prec=0 scale=0
> token.c:1837:col 1:
> token.c:1838: column_name=[type]
> token.c:1844: flags=10 utype=1 type=47 varint=5
> token.c:1847: colsize=4 prec=0 scale=0
> util.c:156:Changed query state from READING to PENDING
> ct.c:1179:ct_results() process_result_tokens returned 1 (type 4049) 
> ct.c:2346:ct_res_info(0x14285c0, 801, 0x1427c88, -99999, (nil))
> ct.c:2346:ct_res_info(0x14285c0, 803, 0x7fff77c3425c, -99999, (nil))
> ct.c:2365:ct_res_info(): Number of columns is 2
> 
> ctlib_bad.log line 417ff
> 
> token.c:548:processing result tokens.  marker is  61(ROWFMT2)
> token.c:577:calling  tds5_process_result2/1
> token.c:1778:tds5_process_result2
> mem.c:660:tds_free_all_results()
> token.c:1802:num_cols=2
> token.c:1868:col 0:
> token.c:1869: column_name=[name]
> token.c:1875: flags=10 utype=42 type=39 server type 39 varint=1
> token.c:1879: colsize=255 prec=0 scale=0
> token.c:1868:col 1:
> token.c:1869: column_name=[type]
> token.c:1875: flags=10 utype=1 type=47 server type 47 varint=1
> token.c:1879: colsize=2 prec=0 scale=0
> token.c:1882:tds5_process_result2(): exit
> mem.c:529:tds_alloc_row()
> mem.c:565:tds_alloc_row(): SUCCESS
> token.c:579: tds5_process_result2() = 0
> util.c:165:Changed query state from READING to PENDING
> ct.c:1215:ct_results() process_result_tokens returned 0 (type 4049) 
> token.c:533:tds_process_tokens(0x18bde20, 0x7ffe79e073b8,
> 0x7ffe79e073bc, 0x6a14)
> util.c:165:Changed query state from PENDING to READING
> token.c:548:processing result tokens.  marker is
> ae(CONTROL/FEATUREEXTACK)
> token.c:132:tds_process_default_tokens() marker is
> ae(CONTROL/FEATUREEXTACK)
> token.c:252:Eating CONTROL/FEATUREEXTACK token
> token.c:548:processing result tokens.  marker is  a9(ORDERBY)
> token.c:132:tds_process_default_tokens() marker is a9(ORDERBY)
> token.c:252:Eating ORDERBY token
> token.c:548:processing result tokens.  marker is  d1(ROW)
> token.c:656:tds_process_tokens::SET_RETURN stopping on current token
> util.c:165:Changed query state from READING to PENDING
> 
> ----
> The related code change was introduced by the following commit.
> 
> > Date: 2016-05-01 00:24:32
> > Revision: 4fea9e776e5475c4c607b9c2fa85a563e6feb700
> > Comment: fix ct-library rows count
> 
> After experimentally adding the following code segment to the switch,
> case CS_ROWFMT_RESULT the application doesn't crash anymore processing
> the results. These lines have been replaced in commit 4fea9. 
> 
> case CS_ROWFMT_RESULT:
>       ...
>       if (context->config.cs_expose_formats) {
>               *result_type = res_type;
>               return CS_SUCCEED;
>       }
>       ...
>       break;
> 
> Instead of crashing, our application is processing quite a few SELECT
> results, but starts hanging in ct_fetch() later, when processing a
> SELECT statements returning 0 rows.
> 
> Got any ideas about this?
> fp
> 

-- 
Fredy Paquet
Mitglied der Geschäftsleitung
OPAG Informatik AG
Fabrikmattenweg 11
CH-4144 Arlesheim
http://www.opag.ch
Tel. ++41 61 716 92 22
Fax. ++41 61 716 92 29

Attachment: smime.p7s
Description: S/MIME cryptographic signature