FreeTDS Development Group

["ZIGLIO, Frediano, VF-IT" <Frediano.Ziglio AT vodafone.com>]

> 
> I'm getting an invalid cursor state error trying to fetch data from a
> stored procedure using prepare/execute from DBD::ODBC.  It looks like
> DBD::ODBC thinks there is more than one result set and is 
> trying to get
> column descriptors when there are no metadata.  
> 
> Actually, there *are* two resultsets: the data, and the return status.
> >From the log, it looks like we tell DBD there's a second 
> resultset but
> then refuse to provide it.  
> 
> This may be related to the db-lib error we found, wherein the
> RETURNSTATUS was not available after dbresults returns 
> NO_MORE_RESULTS.
> I think we may be freeing the return status too soon.  
> 
> Details follow.  
> 
> --jkl
> 
> The perl (dies on the execute line):
> 
>     # call the stored procedure
>     my $sth = $dbh->prepare( $procedure);
>     $sth->execute;
> 

Do die means core or just an error that calls cleanly die functions ??

> The SQL:
> 
> alter procedure IsFreeTdsBroken
> as begin
> 
>       select max(smDate) as LatestInputsmDate
>       from DDMRaw
>       return 0
> end
> 
> The output (wrapped for your viewing pleasure):
> 
> $ perl  jkl simdb..IsFreeTdsBroken
> DBD::ODBC::st fetchrow_array failed: 
>       [unixODBC][FreeTDS][SQL Server]
>               Invalid cursor state (SQL-24000)
>                       (DBD: st_fetch/SQLFetch err=-1) 
>       at jkl line 159.
> 

jkl .... ??? strange name for a program :)

> Some of the log, annotated.  I set TDSDUMP=stderr and DBI_TRACE=3:
> 
> token.c:514:tds_process_tokens() state is COMPLETED
>     SQLPrepare returned 0
> 
>     dbd_st_prepare'd sql f1084704768, ExecDirect=0
>         simdb..IsFreeTdsBroken
>     <- prepare= DBI::st=HASH(0x140a2ffe0) at jkl line 69
>     -> execute for DBD::ODBC::st 
> (DBI::st=HASH(0x140a2ffe0)~0x140a38550)
> error.c:349:odbc_errs_reset
>     dbd_st_execute (for hstmt 1084704768 before)...
> error.c:349:odbc_errs_reset
> odbc.c:2527:End prepare, execute
> query.c:1573:tds_submit_execute()
> util.c:119:Changing query state from IDLE to QUERYING
> mem.c:519:tds_free_all_results()
> util.c:119:Changing query state from QUERYING to PENDING
> net.c:673:Sending packet
> 0000 03 01 00 29 00 00 01 00-0a 00 73 00 70 00 5f 00 
> |...).... ..s.p._.|
> 0010 65 00 78 00 65 00 63 00-75 00 74 00 65 00 00 00 
> |e.x.e.c. u.t.e...|
> 0020 00 00 26 04 04 01 00 00-00                      |..&..... .|
> 
> util.c:119:Changing query state from PENDING to READING
> net.c:446:Received header
> 0000 04 01 00 63 00 5d 01 00-                        |...c.]..|
> 
> net.c:542:Received packet
> 0000 81 01 00 00 00 09 00 6f-04 11 4c 00 61 00 74 00 
> |.......o ..L.a.t.|
> 0010 65 00 73 00 74 00 49 00-6e 00 70 00 75 00 74 00 
> |e.s.t.I. n.p.u.t.|
> 0020 73 00 6d 00 44 00 61 00-74 00 65 00 d1 04 d3 97 
> |s.m.D.a. t.e.....|
> 0030 00 00 ff 11 00 c1 00 01-00 00 00 ff 11 00 c1 00 
> |........ ........|
> 0040 01 00 00 00 ff 01 00 e0-00 01 00 00 00 79 00 00 
> |........ .....y..|
> 0050 00 00 fe 00 00 e0 00 01-00 00 00                |........ ...|
> 
> token.c:526:processing result tokens.  marker is  81(TDS7_RESULT)
> mem.c:519:tds_free_all_results()
> token.c:1472:processing TDS7 result. set current_results to
> tds->res_info
> read.c:179:tds_get_string: reading 34 from wire to give 17 to client.
> token.c:1414:tds7_get_data_info:
>         colname = LatestInputsmDate (17 bytes)
>         type = 111 (datetime-null)
>         server's type = 111 (datetime-null)
>         column_varint_size = 1
>         column_size = 4 (4 on server)
> util.c:119:Changing query state from READING to PENDING
> util.c:119:Changing query state from PENDING to READING
> token.c:526:processing result tokens.  marker is  d1(ROW)
> util.c:119:Changing query state from READING to PENDING
> 
> [So far, so good.  The server executed the query and returned 
> the 1-row,
> 1-column result, a datetime value.]
> 
> dbd_error: err_rc=0 rc=0 s/d/e: 1084704768/1084694528/1084712448
> dbd_error: err_rc=0 rc=0 s/d/e: 0/1084694528/1084712448
> dbd_error: err_rc=0 rc=0 s/d/e: 0/0/1084712448
> 
> [I don't know what these dbd_errors mean these mean.]
> 

Probably DBD::ODBC is tried to get any possible message

> error.c:349:odbc_errs_reset
> error.c:349:odbc_errs_reset
>     dbd_describe sql 1084704768: num_fields=1
> 
> [DBD seems to know that there's one column]
> 
> error.c:349:odbc_errs_reset
> error.c:349:odbc_errs_reset
> odbc.c:1524:odbc:SQLColAttribute: fDescType is 6
> 
> [fDescType 6 is SQL_COLUMN_DISPLAY_SIZE]
> 
> error.c:349:odbc_errs_reset
> odbc.c:1524:odbc:SQLColAttribute: fDescType is 3
> 
> [fDescType 3 is SQL_COLUMN_LENGTH]
> 
>       col  1: TIMESTAMP (93) len=  4 disp= 25, prec=  4 scale=0
> 
> [DBD seems to know it's a 4-byte column displayed in 25 characters]
> 
> error.c:349:odbc_errs_reset
> error.c:349:odbc_errs_reset
>       col  1: 'LatestInputsmDate' sqltype=TIMESTAMP, ctype=SQL_C_CHAR,
> maxlen=25, (dp = 0, cp = 0)
> dbd_describe failed, dbd_st_execute #2...!
> 

Mmmm... and why does dbd_describe fail?? Strange, isn't it?

> [That doesn't look good.  What failed?  But we keep going....]
> 
>     <- execute= -1 at jkl line 70
>     -> fetchrow_array for DBD::ODBC::st
> (DBI::st=HASH(0x140a2ffe0)~0x140a38550)
> 
> [Now DBD will try to fetch the row, which seems to work....]
> 
> error.c:349:odbc_errs_reset
> util.c:119:Changing query state from PENDING to READING
> token.c:526:processing result tokens.  marker is  d1(ROW)
> token.c:1863:tds_get_data: column 0, type 111, varint size 1
> token.c:1920:processing row.  column size is 4
> util.c:119:Changing query state from READING to PENDING
> convert_tds2sql.c:62:convert_tds2sql: src is 58 dest = 1
> convert_tds2sql.c:113:convert_tds2sql: outputting character 
> data destlen
> = 25
>        SQLFetch rc 0
>     dbih_setup_fbav for 1 fields => 0x140a2e700
> fetch num_fields=1
>     <- fetchrow_array= ( '2006-06-01 00:00:00' ) [1 items] row1 at jkl
> line 157 via jkl line 73
>     -> fetchrow_array for DBD::ODBC::st
> (DBI::st=HASH(0x140a2ffe0)~0x140a38550)
> 
> [We returned 25 bytes of converted data to DBD.]
> 
> error.c:349:odbc_errs_reset
> util.c:119:Changing query state from PENDING to READING
> token.c:526:processing result tokens.  marker is  ff(DONEINPROC)
> token.c:2143:tds_process_end: more_results = 1
>                 was_cancelled = 0
>                 error = 0
>                 done_count_valid = 1
> token.c:2175:                rows_affected = 1
> util.c:119:Changing query state from READING to PENDING
> util.c:119:Changing query state from PENDING to READING
> token.c:526:processing result tokens.  marker is  ff(DONEINPROC)
> token.c:2143:tds_process_end: more_results = 1
>                 was_cancelled = 0
>                 error = 0
>                 done_count_valid = 1
> token.c:2175:                rows_affected = 1
> util.c:119:Changing query state from READING to PENDING
> util.c:119:Changing query state from PENDING to READING
> token.c:526:processing result tokens.  marker is  ff(DONEINPROC)
> token.c:2143:tds_process_end: more_results = 1
>                 was_cancelled = 0
>                 error = 0
>                 done_count_valid = 0
> util.c:119:Changing query state from READING to PENDING
> util.c:119:Changing query state from PENDING to READING
> token.c:526:processing result tokens.  marker is  79(RETURNSTATUS)
> token.c:526:processing result tokens.  marker is  fe(DONEPROC)
> token.c:2143:tds_process_end: more_results = 0
>                 was_cancelled = 0
>                 error = 0
>                 done_count_valid = 0
> 
> [Finally, we got the RETURNSTATUS token.  No more results.]
> 
> token.c:2159:tds_process_end() state set to TDS_IDLE
> util.c:119:Changing query state from READING to IDLE
> util.c:119:Changing query state from IDLE to PENDING
> odbc.c:2891:SQLFetch: NO_DATA_FOUND
>        SQLFetch rc 100
> error.c:349:odbc_errs_reset
> token.c:514:tds_process_tokens() state is COMPLETED
> mem.c:519:tds_free_all_results()
> MORE Results!
> 
> [DBD thinks there are more results?  It's expecting the RETURNSTATUS
> value?  But FreeTDS has already freed all results.]
> 

tds_free_all_results do not means that ODBC throwed all infos away, for
instance is has to keep row number information. However... why the hell
does DBI print "MORE Results!"?? Does SQLMoreResults return SQL_SUCCESS
?? I would enable ODBC trace...

> error.c:349:odbc_errs_reset
> error.c:349:odbc_errs_reset
>     dbd_describe sql 1084704768: num_fields=0
>     dbd_describe skipped (no result cols) (sql f1084704768)
> MORE Results dbd_describe success...!
> 
> [DBD discovers there's no resultset (0 columns). An odd kind of
> "success"!]
> 

No problems, ODBC 3 can return resultset without columns...

>     <- fetchrow_array= ( ) [0 items] row1 at jkl line 159 via jkl line
> 73
>     -> FETCH for DBD::ODBC::st (DBI::st=HASH(0x140a38550)~INNER
> 'Active')
>     .. FETCH DBI::st=HASH(0x140a38550) 'Active' = 1
>     <- FETCH= 1 at jkl line 157 via jkl line 73
>     -> fetchrow_array for DBD::ODBC::st
> (DBI::st=HASH(0x140a2ffe0)~0x140a38550)
> 
> [Now DBD tries fetchrow_array again?  Maybe just to find out the
> error....]
> 
> error.c:349:odbc_errs_reset
> error.c:395:odbc_errs_add
> error.c:332:odbc_get_v2state
> error.c:316:odbc_get_msg
> error.c:616:SQLGetDiagRec
> error.c:520:_SQLGetDiagRec 1
> error.c:251:rank_errors
> error.c:564:_SQLGetDiagRec -> [FreeTDS][SQL Server]Invalid 
> cursor state
> error.c:616:SQLGetDiagRec
> error.c:520:_SQLGetDiagRec 2
> 
> [FreeTDS returns 24000]
> 
>        SQLFetch rc -1
> dbd_error: err_rc=-1 rc=0 s/d/e: 1084704768/1084694528/1084712448
> dbd_error: SQL-24000 (native 0): [unixODBC][FreeTDS][SQL 
> Server]Invalid
> cursor state (SQL-24000)
> dbd_error: err_rc=-1 rc=0 s/d/e: 0/1084694528/1084712448
> dbd_error: err_rc=-1 rc=0 s/d/e: 0/0/1084712448
> st_fetch/SQLFetch error -1 recorded: [unixODBC][FreeTDS][SQL
> Server]Invalid cursor state (SQL-24000)(DBD: st_fetch/SQLFetch err=-1)

Here it seems we have (correctly) no data...
James, can you post jkl script source ?

freddy77