FreeTDS Development Group

[Hans Christiansen <hans.christiansen AT apero.se>]

jklowden AT schemamania.org skrev 2011-12-12 16:41:
> On Mon, Dec 12, 2011 at 04:05:12PM +0100, Hans Christiansen wrote:
> > A maintenence task executed nightly has worked well with freeTDS for
> > many months/years now (on Oracle 10/hsodbc/freetds). Upon upgrade to
> > Oracle 11g and dg4odbc I receive the following message after ~ 1 minutes
> > execution.
> ...
> > SQL>  exec weekly_sales.refresh_job_info_cache_week(sysdate-7);
> > /error -28500
> > text: ORA-28500: connection from ORACLE to a non-Oracle system returned this
> > message:/
> > [FreeTDS][SQL Server]Procedure  has no parameters and arguments were
> > supplied. {42000,NativeErr = 8146}
> ...
> > 15:11:41.158760 16157 (query.c:1573):tds_submit_execute()
> > 15:11:41.158766 16157 (util.c:119):Changing query state from IDLE to
> > QUERYING
> > 15:11:41.158772 16157 (mem.c:519):tds_free_all_results()
> > 15:11:41.158779 16157 (query.c:1267):tds_put_data_info putting status
> > 15:11:41.158786 16157 (query.c:1362):tds_put_data: colsize = 0
> > 15:11:41.158792 16157 (query.c:1391):tds_put_data: not null param
> > varint_size = 1
> > 15:11:41.158798 16157 (query.c:1450):swapping numeric data...
> > 15:11:41.158811 16157 (util.c:119):Changing query state from QUERYING to
> > PENDING
> > 15:11:41.158818 16157 (net.c:673):Sending packet
> > 0000 03 01 00 34 00 00 01 00-0a 00 73 00 70 00 5f 00 |...4.... ..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 00 00 6a 04 06 00 04 |..&..... ...j....|
> > 0030 01 9a 31 02            -                        |..1.|
> http://msdn.microsoft.com/en-us/library/ff848746.aspx
>
> You may have snipped off too much of what came earlier in the log.
> The sp_execute procedure takes a handle returned by sp_prepare.  To understand
> the interaction, we'd need to see everything between sp_prepare and 
> sp_execute.
>
> Even then, it won't be easy.  The log may will show what's happening, not why.
> It may expose each ODBC call, and show what Oracle is passing to FreeTDS.  If 
> we
> determine something is missing or done incorrectly, thus explaining the error
> returned by SQL Server, we'll still be left with the question of why Oracle is
> doing it that way.
>
> > From the message, "Procedure  has no parameters and arguments were 
> supplied", it
> would appear the procedure is prepared and executed, but no name was provided
> and no parameters were bound.
>
> HTH.  :-/
>
> --jkl
> _______________________________________________
> FreeTDS mailing list
> FreeTDS AT lists.ibiblio.org
> http://lists.ibiblio.org/mailman/listinfo/freetds

Here is a larger clip from the log. Not sure if I got everything needed 
but more than before.

10:08:31.230396 9713 (odbc.c:2506):Creating prepared statement
10:08:31.230403 9713 (util.c:119):Changing query state from IDLE to QUERYING
10:08:31.230409 9713 (mem.c:519):tds_free_all_results()
10:08:31.230421 9713 (write.c:134):tds_put_string converting 3 bytes of 
"@P1"
10:08:31.230428 9713 (write.c:162):tds_put_string wrote 6 bytes
10:08:31.230435 9713 (util.c:119):Changing query state from QUERYING to 
PENDING
10:08:31.230442 9713 (net.c:673):Sending packet
0000 03 01 01 00 00 00 01 00-ff ff 0b 00 00 00 00 01 |........ ........|
0010 26 04 00 00 00 63 20 00-00 00 0b 04 d0 00 00 20 |&....c . ....... |
0020 00 00 00 40 00 50 00 31-00 20 00 44 00 45 00 43 |...@.P.1 . .D.E.C|
0030 00 49 00 4d 00 41 00 4c-00 28 00 37 00 2c 00 30 |.I.M.A.L .(.7.,.0|
0040 00 29 00 00 00 63 a4 00-00 00 0b 04 d0 00 00 a4 |.)...c.. ........|
0050 00 00 00 53 00 45 00 4c-00 45 00 43 00 54 00 20 |...S.E.L .E.C.T. |
0060 00 22 00 63 00 61 00 6c-00 63 00 5f 00 6d 00 61 |.".c.a.l .c._.m.a|
0070 00 63 00 68 00 69 00 6e-00 65 00 22 00 2c 00 22 |.c.h.i.n .e.".,."|
0080 00 63 00 6f 00 73 00 74-00 5f 00 65 00 64 00 69 |.c.o.s.t ._.e.d.i|
0090 00 74 00 69 00 6f 00 6e-00 22 00 20 00 46 00 52 |.t.i.o.n .". .F.R|
00a0 00 4f 00 4d 00 20 00 22-00 63 00 61 00 6c 00 63 |.O.M. ." .c.a.l.c|
00b0 00 5f 00 6d 00 61 00 74-00 65 00 72 00 69 00 61 |._.m.a.t .e.r.i.a|
00c0 00 6c 00 22 00 20 00 57-00 48 00 45 00 52 00 45 |.l.". .W .H.E.R.E|
00d0 00 20 00 22 00 63 00 61-00 6c 00 63 00 5f 00 6d |. .".c.a .l.c._.m|
00e0 00 61 00 63 00 68 00 69-00 6e 00 65 00 22 00 3d |.a.c.h.i .n.e.".=|
00f0 00 40 00 50 00 31 00 00-00 26 04 04 01 00 00 00 |.@.P.1.. .&......|

10:08:31.230541 9713 (util.c:119):Changing query state from PENDING to 
READING
10:08:31.230801 9713 (net.c:446):Received header
0000 04 01 00 71 00 3e 01 00-                        |...q.>..|

10:08:31.230818 9713 (net.c:542):Received packet
0000 81 02 00 00 00 08 00 38-0c 63 00 61 00 6c 00 63 |.......8 .c.a.l.c|
0010 00 5f 00 6d 00 61 00 63-00 68 00 69 00 6e 00 65 |._.m.a.c .h.i.n.e|
0020 00 00 00 09 00 6a 11 0a-02 0c 63 00 6f 00 73 00 |.....j.. ..c.o.s.|
0030 74 00 5f 00 65 00 64 00-69 00 74 00 69 00 6f 00 |t._.e.d. i.t.i.o.|
0040 6e 00 ff 11 00 c1 00 00-00 00 00 79 00 00 00 00 |n....... ...y....|
0050 ac 0d 00 00 01 00 00 00-00 26 04 04 02 00 02 00 |........ .&......|
0060 fe 00 00 e0 00 00 00 00-00                      |........ .|

10:08:31.230857 9713 (token.c:526):processing result tokens.  marker is  
81(TDS7_RESULT)
10:08:31.230864 9713 (mem.c:519):tds_free_all_results()
10:08:31.230872 9713 (token.c:1472):processing TDS7 result. set 
current_results to tds->res_info
10:08:31.230879 9713 (read.c:179):tds_get_string: reading 24 from wire 
to give 12 to client.
10:08:31.230887 9713 (token.c:1414):tds7_get_data_info:
        colname = calc_machine (12 bytes)
        type = 56 (int)
        server's type = 56 (int)
        column_varint_size = 0
        column_size = 4 (4 on server)
10:08:31.230895 9713 (read.c:179):tds_get_string: reading 24 from wire 
to give 12 to client.
10:08:31.230902 9713 (token.c:1414):tds7_get_data_info:
        colname = cost_edition (12 bytes)
        type = 106 (decimal)
        server's type = 106 (decimal)
        column_varint_size = 1
        column_size = 17 (17 on server)
10:08:31.230910 9713 (token.c:526):processing result tokens.  marker is  
ff(DONEINPROC)
10:08:31.230917 9713 (token.c:2143):tds_process_end: more_results = 1
                was_cancelled = 0
                error = 0
                done_count_valid = 1
10:08:31.230924 9713 (token.c:2175):                rows_affected = 0
10:08:31.230930 9713 (token.c:526):processing result tokens.  marker is  
79(RETURNSTATUS)
10:08:31.230936 9713 (token.c:526):processing result tokens.  marker is  
ac(PARAM)
10:08:31.230943 9713 (token.c:618):processing parameters for sp 11
10:08:31.230949 9713 (token.c:620):calling tds_process_param_result
10:08:31.230956 9713 (token.c:1526):processing result. type = 
38(integer-null), varint_size 1
10:08:31.230963 9713 (token.c:1547):processing result. column_size 4
10:08:31.230969 9713 (token.c:1863):tds_get_data: column 0, type 38, 
varint size 1
10:08:31.230976 9713 (token.c:1920):processing row.  column size is 4
10:08:31.230982 9713 (token.c:624):no of hidden return parameters 1
10:08:31.230989 9713 (token.c:526):processing result tokens.  marker is  
fe(DONEPROC)
10:08:31.230995 9713 (token.c:2143):tds_process_end: more_results = 0
                was_cancelled = 0
                error = 0
                done_count_valid = 0
10:08:31.231002 9713 (token.c:2159):tds_process_end() state set to TDS_IDLE
10:08:31.231008 9713 (util.c:119):Changing query state from READING to IDLE
10:08:31.231014 9713 (util.c:119):Changing query state from IDLE to PENDING
10:08:31.231020 9713 (token.c:514):tds_process_tokens() state is COMPLETED
10:08:31.231026 9713 (odbc.c:2527):End prepare, execute
10:08:31.231032 9713 (query.c:1573):tds_submit_execute()
10:08:31.231048 9713 (util.c:119):Changing query state from IDLE to QUERYING
10:08:31.231055 9713 (mem.c:519):tds_free_all_results()
10:08:31.231062 9713 (query.c:1267):tds_put_data_info putting status
10:08:31.231068 9713 (query.c:1362):tds_put_data: colsize = 0
10:08:31.231074 9713 (query.c:1391):tds_put_data: not null param 
varint_size = 1
10:08:31.231080 9713 (query.c:1450):swapping numeric data...
10:08:31.231086 9713 (util.c:119):Changing query state from QUERYING to 
PENDING
10:08:31.231092 9713 (net.c:673):Sending packet
0000 03 01 00 34 00 00 01 00-0a 00 73 00 70 00 5f 00 |...4.... ..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 02 00 01-00 00 00 6a 04 07 00 04 |..&..... ...j....|
0030 01 9a 25 2a            -                        |..%*|

10:08:31.231125 9713 (util.c:119):Changing query state from PENDING to 
READING
10:08:31.231475 9713 (net.c:446):Received header
0000 04 01 00 be 00 3e 01 00-                        |.....>..|

10:08:31.231492 9713 (net.c:542):Received packet
0000 aa aa 00 d2 1f 00 00 01-10 39 00 50 00 72 00 6f |........ .9.P.r.o|
0010 00 63 00 65 00 64 00 75-00 72 00 65 00 20 00 20 |.c.e.d.u .r.e. . |
0020 00 68 00 61 00 73 00 20-00 6e 00 6f 00 20 00 70 |.h.a.s.  .n.o. .p|
0030 00 61 00 72 00 61 00 6d-00 65 00 74 00 65 00 72 |.a.r.a.m .e.t.e.r|
0040 00 73 00 20 00 61 00 6e-00 64 00 20 00 61 00 72 |.s. .a.n .d. .a.r|
0050 00 67 00 75 00 6d 00 65-00 6e 00 74 00 73 00 20 |.g.u.m.e .n.t.s. |
0060 00 77 00 65 00 72 00 65-00 20 00 73 00 75 00 70 |.w.e.r.e . .s.u.p|
0070 00 70 00 6c 00 69 00 65-00 64 00 2e 00 16 47 00 |.p.l.i.e .d....G.|
0080 52 00 41 00 46 00 55 00-53 00 45 00 52 00 56 00 |R.A.F.U. S.E.R.V.|
0090 45 00 52 00 5c 00 53 00-51 00 4c 00 45 00 58 00 |E.R.\.S. Q.L.E.X.|
00a0 50 00 52 00 45 00 53 00-53 00 00 01 00 fe 02 00 |P.R.E.S. S.......|
00b0 e0 00 00 00 00 00      -                        |......|

10:08:31.231554 9713 (token.c:526):processing result tokens.  marker is  
aa(ERROR)
10:08:31.231561 9713 (token.c:105):tds_process_default_tokens() marker 
is aa(ERROR)
10:08:31.231568 9713 (token.c:2439):tds_process_msg() reading message 
from server
10:08:31.231575 9713 (read.c:179):tds_get_string: reading 114 from wire 
to give 57 to client.
10:08:31.231585 9713 (read.c:179):tds_get_string: reading 44 from wire 
to give 22 to client.
10:08:31.231594 9713 (token.c:2501):tds_process_msg() calling client msg 
handler
10:08:31.231605 9713 (token.c:2514):tds_process_msg() returning TDS_SUCCEED
10:08:31.231612 9713 (token.c:526):processing result tokens.  marker is  
fe(DONEPROC)
10:08:31.231619 9713 (token.c:2143):tds_process_end: more_results = 0
                was_cancelled = 0
                error = 1
                done_count_valid = 0
10:08:31.231626 9713 (token.c:2159):tds_process_end() state set to TDS_IDLE
10:08:31.231631 9713 (util.c:119):Changing query state from READING to IDLE
10:08:31.231638 9713 (util.c:119):Changing query state from IDLE to PENDING


The statement seems correct, and is performed a number of times prior to 
the error occuring.

Any ideas?

/Hans


--

*Apero Solutions AB*

Box 104, S-264 22 Klippan

Telephone: +46-435 77 91 21

www.apero.se <http://www.apero.se>