FreeTDS Development Group

["Lowden, James K" <LowdenJK AT bernstein.com>]

> From: Ben Vaughn [mailto:bvaughn AT BlackbirdTech.com]
> Sent: July 22, 2003 11:13 AM
> 
> 2003-07-22 14:53:55.977343 processing result tokens.  marker is
> ee(RESULT)
> 2003-07-22 14:53:55.977371 processing result. type = 108(numeric),
> varint_size 1
> 2003-07-22 14:53:55.977385 processing result. column_size 9
...

This is good.  You get a result token and 14 columns:

     1  processing result. type = 108(numeric), varint_size 1
     2  processing result. type = 61(datetime), varint_size 0
     3  processing result. type =  111(datetime-null), varint_size 1
     4  processing result. type = 38(integer-null), varint_size 1
     5  processing result. type = 108(numeric), varint_size 1
     6  processing result. type = 108(numeric), varint_size 1
     7  processing result. type = 108(numeric), varint_size 1
     8  processing result. type = 108(numeric), varint_size 1
     9  processing result. type = 39(varchar), varint_size 1
    10  processing result. type = 38(integer-null), varint_size 1
    11  processing result. type = 108(numeric), varint_size 1
    12  processing result. type = 39(varchar), varint_size 1
    13  processing result. type = 38(integer-null), varint_size 1
    14  processing result. type = 34(image), varint_size 4

> 2003-07-22 14:53:55.977839 processing result tokens.  marker 
> is  d1(ROW)
...
> 2003-07-22 14:53:55.978231 processing row.  column is 9 
> varint size = 1
> 2003-07-22 14:53:55.978245 processing row.  column size is 8
> 2003-07-22 14:53:55.978256 clearing column 9 NULL bit
> 2003-07-22 14:53:55.978484 processing row tokens.  marker is  
> a1(COLFMT)

Now we got a row, but only 10 columns?  

> 2003-07-22 14:53:55.978501 inside 
> tds_process_default_tokens() marker is
> a1(COLFMT)
> 2003-07-22 14:53:55.978515 processing result. type = 0(), 
> varint_size 1

Here we clearly begin to misinterpret the data stream.  Let's back up and
parse it manually, to see if we can determine where things went awry.  

Received header @ 2003-07-22 14:53:55.976843
0000  04 00 01 f3 00 00 00 00                            |........|
         ^^ partial packet follows

   Received packet @ 2003-07-22 14:53:55.976892
0000  ee 1f 01 : TDS_ROWFMT is 0x1f1 == 497 bytes long
      0e 00 : 14 columns

(1)   02 49 44 : "ID"
      10 : updatable
      0d 00 00 00 : user type 13
      6c : data type 108(numeric)
      09 : max length 9
      13 : precision 19
      00 : scale 0
      00 : no locale
(2)   0a 41 4c 45 52 54 5f 54 49 4d 45 : "ALERT_TIME"
      10 : updatable
      50 00 00 00 : user type
      3d : data type 61(datetime)
      00 : max length (fixed)
(3)   08 49 44 53  5f 54 49 4d 45 : "IDS_TIME"
      20 
      50 00 00 00 
      6f 
      08 
      00 
(4)   08 53 45  56 45 52 49 54 59 : "SEVERITY"
      30 
      05 00 00 00 
      26 
      01 
      00 
(5)   06 49  44 53 5f 49 44 : "IDS_ID"
      30 
      0d 00 00 00 
      6c 
      05 
      09 
      00 
      00 
(6)   0c  53 49 47 4e 41 54 55 52 45 5f 49 44 : "SIGNATURE_ID"
      30 
      0d 00 00 00 
      6c 
      05 
      09 
      00 
      00 
(7)   0d 53 53 49 47 4e 41 54 55 52  45 5f 49 44 : "SSIGNATURE_ID"
      30 
      0d 00 00 00 
      6c 
      05 
      09 
      00 
      00 
(8)   06 53  52 43 5f 49 50 : "SRC_IP"
      30 
      0d 00 00 00 
      6c 
      05 
      09 
      00 
      00 
(9)   0c 53 52 43 5f 4c 4f 43 41 4c 49 54 59 :"SRC_LOCALITY"
      30 
      02 00 00 00 
      27 
      11 
      00 
(10)  08 53 52 43 5f 50 4f 52 54 : "SRC_PORT"
      30 
      07 00 00 00 
      26 
      04 
      00 
(11)  06 44 53 54 5f 49 50 : "DST_IP"
      30 
      0d 00 00 00 
      6c 
      05 
      09 
      00 
      00 
(12)  0c 44 53 54 5f 4c 4f 43 41 4c  49 54 59 : "DST_LOCALITY"
      30 
      02 00 00 00
      27 
      11 
      00 
(13)  08 44 53 54 5f  50 4f 52 54 : "DST_PORT"
      30 
      07 00 00 00 
      26 
      04 
      00 
(14)  07 44 45 54  41 49 4c 53 : "DETAILS"
      30 
      03 00 00 00 
      22 : type = 34(image)
      00 fc 00 00 : max length 64512
      19 00 : ClassID length = 25 bytes
      69 64 73 6d 64 63 2e 69  64 73 6d 64 63 2e 41 4c 
      45 52 54 5f 54 41 42 4c 45 
              : ClassID = "idsmdc.idsmdc.ALERT_TABLE"
      00 ???

I don't recognize that null, but it must be OK.  We continue with the next
TDS packet, a row of data.  These are length-data pairs, except that fixed
length types have no length component.  

      d1 TDS_ROW token
(1)   09 : "ID", 108(numeric)
      00 00 00 00  00 00 41 e1 a7 
(2)   be 93 00 00 25 49 a0 00 : "ALERT_TIME", 61(datetime)
(3)   08 : "IDS_TIME", 111(datetime-null)
      be 93 00 00 6c 32 f7 00 
(4)   01 : "SEVERITY", 38(integer-null)
      02 
(5)   05 : "IDS_ID", 108(numeric)
      00 00 00 00 06 
(6)   05 : "SIGNATURE_ID", 108(numeric)
      00 00 00 0f a1 
(7)   05 : "SSIGNATURE_ID", 108(numeric)
      00 00 00 00 00 
(8)   05 : "SRC_IP", 108(numeric)
      00 00 00 00 00 
(9)   03 :"SRC_LOCALITY", 39(varchar)
      4f 55 54 
(10)  08 : "SRC_PORT", 38(integer-null)
      a1 00 00 00 00 00 00 00 
      ^^ see below.  
(11)  05 : "DST_IP", 108(numeric)
      00 00 00 00 00 
(12)  02 : "DST_LOCALITY", 39(varchar)
      49 4e 
(13)  08 : "DST_PORT", 38(integer-null)
      e2 10 00 00 00 00 00 00 
(14)  10 21 24 01 : "DETAILS", 34(image)

$ printf "%d\n" 0x21101024
554700836

That's 554,700,836 bytes of "DETAILS"! :-)  The rest would be in the next
packet(s).  

We go wrong around SRC_PORT.  The log says:

> 2003-07-22 14:53:55.978245 processing row.  column size is 8
> 2003-07-22 14:53:55.978256 clearing column 9 NULL bit
> 2003-07-22 14:53:55.978484 processing row tokens.  marker is  
> a1(COLFMT)
> 2003-07-22 14:53:55.978501 inside 
> tds_process_default_tokens() marker is
> a1(COLFMT)

It sure looks as if the row meta data got hurt.  Instead of reading 8 bytes
for "SRC_PORT", we clear the null bit and drop out of the row processor,
looking for a new token.  We find (what we think is) one, 0xa1, but that's
actually the first byte of the SRC_PORT data.  It gets ugly after that.  

I don't have a fix.  I have some suggestions.  

The row data are read in loop in src/tds/token.c::tds_process_row().  Try
writing info->num_cols to the log on entering and leaving that function,
just to be sure it's not being overwritten.  

tds_process_row() calls tds_get_data(), which returns TDS_FAIL without
reading the data if it detects any problem.  That would conform to what the
log shows: interpreting the column's data as a token.  Unfortunately,
tds_get_data() doesn't usually log why it failed.  

SRC_PORT is an integer-null type, one of the simpler data types.  You're
using the 0.61 release.  The only TDS_FAIL return I see for integers is
src/tds/token.c line 1388.  I'd like to know what colsize and
curcol->column_size are for SRC_PORT.  Perhaps change the code to be
(notional patch):

        if (curcol->column_unicodedata) {
                colsize /= 2;
                /* server is going to crash freetds ?? */
                if (colsize > curcol->column_size)
                        return TDS_FAIL;
                tds_get_string(tds, (char *) dest, colsize);
                } else {
                        /* server is going to crash freetds ?? */
-                       if (colsize > curcol->column_size) 
+                       if (colsize > curcol->column_size) {
+                               tdsdump_log(TDS_DBG_INFO1, 
+                                       "%L colsize (%d) >
curcol->column_size (%d)!\n",
                                        colsize, curcol->column_size);
                                return TDS_FAIL;
+                       }
                        tds_get_n(tds, dest, colsize);
                }
        ...

If nothing else, that should yield up some more information.  

If you want to go down the road of debugging this, you're best off getting
the latest snapshot or using CVS.  That way, I can keep making the log more
verbose until it becomes clear what's happening, fix it, and cross it off
the list.  I'd rather not use 0.61 as a starting point; too much has changed
since.  

HTH.  

+++

There's a lesson in this, at least for me.  Looking at the error path, it's
quite obvious we're being silly:  

        tds_get_data() returns TDS_FAIL to 
        tds_process_row() returns TDS_FAIL

but that return code is roundly ignored.  We're now at a point in this
project where we expect to be able to interpret everything the server sends
us.  If we know we're punting, we should fail hard and noisily.  There's no
point in stupidly trying to read the stream after abandoning the stream in
mid-packet.  

--jkl
-----------------------------------------
The information contained in this transmission may contain privileged and 
confidential information and is intended only for the use of the person(s) 
named above. If you are not the intended recipient, or an employee or agent 
responsible for delivering this message to the intended recipient, any 
review, dissemination, distribution or duplication of this communication is 
strictly prohibited. If you are not the intended recipient, please contact 
the sender immediately by reply e-mail and destroy all copies of the original 
message. Please note that we do not accept account orders and/or instructions 
by e-mail, and therefore will not be responsible for carrying out such orders 
and/or instructions.