FreeTDS Development Group

["Luke Benstead" <kazade AT gmail.com>]

Dear all,

I have been using PyODBC to write cross platform code that connects to an
MS-SQL database which uses freetds. Earlier today we discovered a strange
bug that only occurs on linux. We have a query which is the following:

SELECT ID
FROM  vwSomeView
WHERE (EmailAddress = 'someone AT email.com')

Besides the column name, view name and email address that is the complete
query. There IS only 1 result in the database that matches that email
address. On Windows we get one result back. On linux we get back 2 rows; the
same row twice.

At first I suspected PyODBC but looking at the code it doesn't seem to do
much except call SQLFetch() and there is no linux specific code. So I turned
up the logging on freetds which gives me the following:

13:49:02.901895 processing result tokens.  marker is  fd(DONE)
13:49:02.901933 tds_process_end: more_results = 1
       was_cancelled = 0
       error = 0
       done_count_valid = 0
13:49:02.901948 processing result tokens.  marker is  fd(DONE)
13:49:02.901960 tds_process_end: more_results = 1
       was_cancelled = 0
       error = 0
       done_count_valid = 0
13:49:02.901971 processing result tokens.  marker is  fd(DONE)
13:49:02.901983 tds_process_end: more_results = 0
       was_cancelled = 0
       error = 0
       done_count_valid = 0

which looks to me like it processes the row twice.

What makes this bug even more odd is that if I replace:

'SELECT ID' with 'SELECT *' only one row is returned.

I was using freetds version 0.63 (the one that comes with Ubuntu Feisty) but
i downloaded and installed the latest CVS snapshot and that does the same
thing. I have attached the log so that hopefully someone can help with my
problem.

Thanks,

Luke.
13:49:00.265432 Starting log file for FreeTDS 0.63
	on 2007-05-16 13:49:00 with debug level 99.
13:49:00.265514 names for ISO-8859-1: ISO-8859-1
13:49:00.265527 names for UTF-8: UTF-8
13:49:00.265539 names for UCS-2LE: UCS-2LE
13:49:00.265549 names for UCS-2BE: UCS-2BE
13:49:00.265560 iconv to convert client-side data to the "UTF8" character set
13:49:00.265595 tds_iconv_info_init: converting "UTF-8"->"UCS-2LE"
13:49:00.265629 tds_iconv_info_init: converting "ISO-8859-1"->"UCS-2LE"
13:49:00.265653 Connecting to 192.168.60.1 port 1433, TDS 7.0.
13:49:00.369751 tds_put_string converting 6 bytes of "hughes"
13:49:00.369831 tds_put_string wrote 12 bytes
13:49:00.369849 tds_put_string converting 9 bytes of "RSLTester"
13:49:00.369867 tds_put_string wrote 18 bytes
13:49:00.369884 tds_put_string wrote 0 bytes
13:49:00.369898 tds_put_string converting 8 bytes of "EMMANUEL"
13:49:00.369914 tds_put_string wrote 16 bytes
13:49:00.369928 tds_put_string wrote 0 bytes
13:49:00.369942 tds_put_string converting 10 bytes of "us_english"
13:49:00.369959 tds_put_string wrote 20 bytes
13:49:00.369974 tds_put_string converting 33 bytes of "HobsonsCandidate2003BInternalTest"
13:49:00.369991 tds_put_string wrote 66 bytes
13:49:00.370042 tds_process_login_tokens()
13:49:00.619802 Received header
0000 04 01 02 0c 00 ac 01 00-                        |........|

13:49:00.619861 Received packet
0000 e3 51 00 01 21 48 00 6f-00 62 00 73 00 6f 00 6e |.Q..!H.o .b.s.o.n|
0010 00 73 00 43 00 61 00 6e-00 64 00 69 00 64 00 61 |.s.C.a.n .d.i.d.a|
0020 00 74 00 65 00 32 00 30-00 30 00 33 00 42 00 49 |.t.e.2.0 .0.3.B.I|
0030 00 6e 00 74 00 65 00 72-00 6e 00 61 00 6c 00 54 |.n.t.e.r .n.a.l.T|
0040 00 65 00 73 00 74 00 06-6d 00 61 00 73 00 74 00 |.e.s.t.. m.a.s.t.|
0050 65 00 72 00 ab 9c 00 45-16 00 00 02 00 40 00 43 |e.r....E .....@.C|
0060 00 68 00 61 00 6e 00 67-00 65 00 64 00 20 00 64 |.h.a.n.g .e.d. .d|
0070 00 61 00 74 00 61 00 62-00 61 00 73 00 65 00 20 |.a.t.a.b .a.s.e. |
0080 00 63 00 6f 00 6e 00 74-00 65 00 78 00 74 00 20 |.c.o.n.t .e.x.t. |
0090 00 74 00 6f 00 20 00 27-00 48 00 6f 00 62 00 73 |.t.o. .' .H.o.b.s|
00a0 00 6f 00 6e 00 73 00 43-00 61 00 6e 00 64 00 69 |.o.n.s.C .a.n.d.i|
00b0 00 64 00 61 00 74 00 65-00 32 00 30 00 30 00 33 |.d.a.t.e .2.0.0.3|
00c0 00 42 00 49 00 6e 00 74-00 65 00 72 00 6e 00 61 |.B.I.n.t .e.r.n.a|
00d0 00 6c 00 54 00 65 00 73-00 74 00 27 00 2e 00 08 |.l.T.e.s .t.'....|
00e0 45 00 4d 00 4d 00 41 00-4e 00 55 00 45 00 4c 00 |E.M.M.A. N.U.E.L.|
00f0 00 00 00 e3 17 00 02 0a-75 00 73 00 5f 00 65 00 |........ u.s._.e.|
0100 6e 00 67 00 6c 00 69 00-73 00 68 00 00 ab 6a 00 |n.g.l.i. s.h...j.|
0110 47 16 00 00 01 00 27 00-43 00 68 00 61 00 6e 00 |G.....'. C.h.a.n.|
0120 67 00 65 00 64 00 20 00-6c 00 61 00 6e 00 67 00 |g.e.d. . l.a.n.g.|
0130 75 00 61 00 67 00 65 00-20 00 73 00 65 00 74 00 |u.a.g.e.  .s.e.t.|
0140 74 00 69 00 6e 00 67 00-20 00 74 00 6f 00 20 00 |t.i.n.g.  .t.o. .|
0150 75 00 73 00 5f 00 65 00-6e 00 67 00 6c 00 69 00 |u.s._.e. n.g.l.i.|
0160 73 00 68 00 2e 00 08 45-00 4d 00 4d 00 41 00 4e |s.h....E .M.M.A.N|
0170 00 55 00 45 00 4c 00 00-00 00 e3 0f 00 03 05 69 |.U.E.L.. .......i|
0180 00 73 00 6f 00 5f 00 31-00 01 00 00 e3 0b 00 05 |.s.o._.1 ........|
0190 04 31 00 30 00 33 00 33-00 00 e3 0f 00 06 06 31 |.1.0.3.3 .......1|
01a0 00 39 00 36 00 36 00 30-00 39 00 00 ad 36 00 01 |.9.6.6.0 .9...6..|
01b0 07 00 00 00 16 4d 00 69-00 63 00 72 00 6f 00 73 |.....M.i .c.r.o.s|
01c0 00 6f 00 66 00 74 00 20-00 53 00 51 00 4c 00 20 |.o.f.t.  .S.Q.L. |
01d0 00 53 00 65 00 72 00 76-00 65 00 72 00 00 00 00 |.S.e.r.v .e.r....|
01e0 00 08 00 03 32 e3 13 00-04 04 34 00 30 00 39 00 |....2... ..4.0.9.|
01f0 36 00 04 34 00 30 00 39-00 36 00 fd 00 00 00 00 |6..4.0.9 .6......|
0200 00 00 00 00            -                        |....|

13:49:00.620048 looking for login token, got  e3(ENVCHANGE)
13:49:00.620073 tds_process_default_tokens() marker is e3(ENVCHANGE)
13:49:00.620091 tds_get_string: reading 66 from wire to give 33 to client.
13:49:00.620118 tds_get_string: reading 12 from wire to give 6 to client.
13:49:00.620137 looking for login token, got  ab(INFO)
13:49:00.620162 tds_process_default_tokens() marker is ab(INFO)
13:49:00.620175 tds_get_string: reading 128 from wire to give 64 to client.
13:49:00.620189 tds_get_string: reading 16 from wire to give 8 to client.
13:49:00.620213 looking for login token, got  e3(ENVCHANGE)
13:49:00.620224 tds_process_default_tokens() marker is e3(ENVCHANGE)
13:49:00.620236 tds_get_string: reading 20 from wire to give 10 to client.
13:49:00.620249 looking for login token, got  ab(INFO)
13:49:00.620260 tds_process_default_tokens() marker is ab(INFO)
13:49:00.620272 tds_get_string: reading 78 from wire to give 39 to client.
13:49:00.620285 tds_get_string: reading 16 from wire to give 8 to client.
13:49:00.620304 looking for login token, got  e3(ENVCHANGE)
13:49:00.620315 tds_process_default_tokens() marker is e3(ENVCHANGE)
13:49:00.620326 tds_get_string: reading 10 from wire to give 5 to client.
13:49:00.620339 tds_get_string: reading 2 from wire to give 1 to client.
13:49:00.620385 tds_iconv_info_init: converting "UTF-8"->"ISO-8859-1"
13:49:00.620398 looking for login token, got  e3(ENVCHANGE)
13:49:00.620409 tds_process_default_tokens() marker is e3(ENVCHANGE)
13:49:00.620421 tds_get_string: reading 8 from wire to give 4 to client.
13:49:00.620434 looking for login token, got  e3(ENVCHANGE)
13:49:00.620445 tds_process_default_tokens() marker is e3(ENVCHANGE)
13:49:00.620457 tds_get_string: reading 12 from wire to give 6 to client.
13:49:00.620470 looking for login token, got  ad(LOGINACK)
13:49:00.620481 tds_get_string: reading 44 from wire to give 22 to client.
13:49:00.620494 looking for login token, got  e3(ENVCHANGE)
13:49:00.620505 tds_process_default_tokens() marker is e3(ENVCHANGE)
13:49:00.620516 tds_get_string: reading 8 from wire to give 4 to client.
13:49:00.620529 tds_get_string: reading 8 from wire to give 4 to client.
13:49:00.620542 increasing block size from 4096 to 4096
13:49:00.620565 looking for login token, got  fd(DONE)
13:49:00.620577 tds_process_default_tokens() marker is fd(DONE)
13:49:00.620588 tds_process_end: more_results = 0
		was_cancelled = 0
		error = 0
		done_count_valid = 0
13:49:00.620600 tds_process_end() state set to TDS_IDLE
13:49:00.620611 leaving tds_process_login_tokens() returning 1
13:49:00.620628 SQLGetFunctions: fFunction is 999
13:49:00.620667 change_autocommit: executing SET IMPLICIT_TRANSACTIONS ON
13:49:00.620683 tds_free_all_results()
13:49:00.620695 tds_put_string converting 28 bytes of "SET IMPLICIT_TRANSACTIONS ON"
13:49:00.620709 tds_put_string wrote 56 bytes
13:49:00.620720 Sending packet
0000 01 01 00 40 00 00 01 00-53 00 45 00 54 00 20 00 |...@.... S.E.T. .|
0010 49 00 4d 00 50 00 4c 00-49 00 43 00 49 00 54 00 |I.M.P.L. I.C.I.T.|
0020 5f 00 54 00 52 00 41 00-4e 00 53 00 41 00 43 00 |_.T.R.A. N.S.A.C.|
0030 54 00 49 00 4f 00 4e 00-53 00 20 00 4f 00 4e 00 |T.I.O.N. S. .O.N.|

13:49:00.648002 Received header
0000 04 01 00 11 00 ac 01 00-                        |........|

13:49:00.648042 Received packet
0000 fd 00 00 b9 00 00 00 00-00                      |........ .|

13:49:00.648055 processing result tokens.  marker is  fd(DONE)
13:49:00.648085 tds_process_end: more_results = 0
		was_cancelled = 0
		error = 0
		done_count_valid = 0
13:49:00.648097 tds_process_end() state set to TDS_IDLE
13:49:00.648108 tds_process_result_tokens() state is COMPLETED
13:49:00.648810 tds_free_all_results()
13:49:00.648840 tds_put_string converting 107 bytes of "	SELECT GoldmineID
					FROM  vwOrganizationContact
					WHERE (EmailAddress = 'hugh.jaques AT eu.effem.com') "
13:49:00.648859 tds_put_string wrote 214 bytes
13:49:00.648870 Sending packet
0000 01 01 00 de 00 00 01 00-09 00 53 00 45 00 4c 00 |........ ..S.E.L.|
0010 45 00 43 00 54 00 20 00-47 00 6f 00 6c 00 64 00 |E.C.T. . G.o.l.d.|
0020 6d 00 69 00 6e 00 65 00-49 00 44 00 0a 00 09 00 |m.i.n.e. I.D.....|
0030 09 00 09 00 09 00 09 00-46 00 52 00 4f 00 4d 00 |........ F.R.O.M.|
0040 20 00 20 00 76 00 77 00-4f 00 72 00 67 00 61 00 | . .v.w. O.r.g.a.|
0050 6e 00 69 00 7a 00 61 00-74 00 69 00 6f 00 6e 00 |n.i.z.a. t.i.o.n.|
0060 43 00 6f 00 6e 00 74 00-61 00 63 00 74 00 0a 00 |C.o.n.t. a.c.t...|
0070 09 00 09 00 09 00 09 00-09 00 57 00 48 00 45 00 |........ ..W.H.E.|
0080 52 00 45 00 20 00 28 00-45 00 6d 00 61 00 69 00 |R.E. .(. E.m.a.i.|
0090 6c 00 41 00 64 00 64 00-72 00 65 00 73 00 73 00 |l.A.d.d. r.e.s.s.|
00a0 20 00 3d 00 20 00 27 00-68 00 75 00 67 00 68 00 | .=. .'. h.u.g.h.|
00b0 2e 00 6a 00 61 00 71 00-75 00 65 00 73 00 40 00 |..j.a.q. u.e.s.@.|
00c0 65 00 75 00 2e 00 65 00-66 00 66 00 65 00 6d 00 |e.u...e. f.f.e.m.|
00d0 2e 00 63 00 6f 00 6d 00-27 00 29 00 20 00       |..c.o.m. '.). .|

13:49:02.789394 Received header
0000 04 01 00 e9 00 ac 01 00-                        |........|

13:49:02.789445 Received packet
0000 81 01 00 00 00 09 00 a7-0a 00 0a 47 00 6f 00 6c |........ ...G.o.l|
0010 00 64 00 6d 00 69 00 6e-00 65 00 49 00 44 00 d1 |.d.m.i.n .e.I.D..|
0020 05 00 38 31 39 30 55 ab-ae 00 d9 1f 00 00 01 00 |..8190U. ........|
0030 49 00 57 00 61 00 72 00-6e 00 69 00 6e 00 67 00 |I.W.a.r. n.i.n.g.|
0040 3a 00 20 00 4e 00 75 00-6c 00 6c 00 20 00 76 00 |:. .N.u. l.l. .v.|
0050 61 00 6c 00 75 00 65 00-20 00 69 00 73 00 20 00 |a.l.u.e.  .i.s. .|
0060 65 00 6c 00 69 00 6d 00-69 00 6e 00 61 00 74 00 |e.l.i.m. i.n.a.t.|
0070 65 00 64 00 20 00 62 00-79 00 20 00 61 00 6e 00 |e.d. .b. y. .a.n.|
0080 20 00 61 00 67 00 67 00-72 00 65 00 67 00 61 00 | .a.g.g. r.e.g.a.|
0090 74 00 65 00 20 00 6f 00-72 00 20 00 6f 00 74 00 |t.e. .o. r. .o.t.|
00a0 68 00 65 00 72 00 20 00-53 00 45 00 54 00 20 00 |h.e.r. . S.E.T. .|
00b0 6f 00 70 00 65 00 72 00-61 00 74 00 69 00 6f 00 |o.p.e.r. a.t.i.o.|
00c0 6e 00 2e 00 08 45 00 4d-00 4d 00 41 00 4e 00 55 |n....E.M .M.A.N.U|
00d0 00 45 00 4c 00 00 01 00-fd 10 00 c1 00 01 00 00 |.E.L.... ........|
00e0 00                     -                        |.|

13:49:02.789527 processing result tokens.  marker is  81(TDS7_RESULT)
13:49:02.789566 tds_free_all_results()
13:49:02.789582 processing TDS7 result. set current_results to tds->res_info
13:49:02.789602 adjust_character_column_size:
	Server charset: ISO-8859-1
	Server column_size: 10
	Client charset: UTF-8
	Client column_size: 40
13:49:02.789614 tds_get_string: reading 20 from wire to give 10 to client.
13:49:02.789631 tds7_get_data_info:1558: 
	colname = GoldmineID (10 bytes)
	type = 39 (varchar)
	server's type = 167 (xvarchar)
	column_varint_size = 2
	column_size = 40 (10 on server)
13:49:02.789648 processing result tokens.  marker is  d1(ROW)
13:49:02.789722 processing row tokens.  marker is  d1(ROW)
13:49:02.789735 processing row.  column is 0 varint size = 2
13:49:02.789746 processing row.  column size is 5 
13:49:02.789757 clearing column 0 NULL bit
13:49:02.789790 convert_tds2sql: src is 39 dest = 1
13:49:02.789813 convert_tds2sql: outputting character data destlen = 2048 
13:49:02.789830 processing row tokens.  marker is  ab(INFO)
13:49:02.789842 tds_process_default_tokens() marker is ab(INFO)
13:49:02.789855 tds_get_string: reading 146 from wire to give 73 to client.
13:49:02.789869 tds_get_string: reading 16 from wire to give 8 to client.
13:49:02.789895 processing row tokens.  marker is  fd(DONE)
13:49:02.789907 tds_process_end: more_results = 0
		was_cancelled = 0
		error = 0
		done_count_valid = 1
13:49:02.789920 tds_process_end() state set to TDS_IDLE
13:49:02.789930                 rows_affected = 1
13:49:02.789943 SQLFetch: NO_DATA_FOUND
13:49:02.789970 convert_tds2sql: src is 39 dest = 1
13:49:02.789982 convert_tds2sql: outputting character data destlen = 2048 
13:49:02.789996 tds_process_row_tokens() state is COMPLETED
13:49:02.790009 SQLFetch: NO_DATA_FOUND
13:49:02.792227 SQLTransact(0x(nil),0x0x820f1b8,1)
13:49:02.792270 change_transaction(0x0x820f1b8,0)
13:49:02.792283 tds_free_all_results()
13:49:02.792298 tds_put_string converting 27 bytes of "IF @@TRANCOUNT > 0 ROLLBACK"
13:49:02.792315 tds_put_string wrote 54 bytes
13:49:02.792327 Sending packet
0000 01 01 00 3e 00 00 01 00-49 00 46 00 20 00 40 00 |...>.... I.F. .@.|
0010 40 00 54 00 52 00 41 00-4e 00 43 00 4f 00 55 00 |@.T.R.A. N.C.O.U.|
0020 4e 00 54 00 20 00 3e 00-20 00 30 00 20 00 52 00 |N.T. .>.  .0. .R.|
0030 4f 00 4c 00 4c 00 42 00-41 00 43 00 4b 00       |O.L.L.B. A.C.K.|

13:49:02.901827 Received header
0000 04 01 00 23 00 ac 01 00-                        |...#....|

13:49:02.901876 Received packet
0000 fd 01 00 c0 00 00 00 00-00 fd 01 00 d2 00 00 00 |........ ........|
0010 00 00 fd 00 00 ca 00 00-00 00 00                |........ ...|

13:49:02.901895 processing result tokens.  marker is  fd(DONE)
13:49:02.901933 tds_process_end: more_results = 1
		was_cancelled = 0
		error = 0
		done_count_valid = 0
13:49:02.901948 processing result tokens.  marker is  fd(DONE)
13:49:02.901960 tds_process_end: more_results = 1
		was_cancelled = 0
		error = 0
		done_count_valid = 0
13:49:02.901971 processing result tokens.  marker is  fd(DONE)
13:49:02.901983 tds_process_end: more_results = 0
		was_cancelled = 0
		error = 0
		done_count_valid = 0
13:49:02.901994 tds_process_end() state set to TDS_IDLE
13:49:02.902005 tds_process_result_tokens() state is COMPLETED
13:49:02.902031 tds_free_all_results()
13:49:02.902086 SQLFreeHandle(2, 0x0x820f1b8)
13:49:02.902100 SQLFreeHandle(1, 0x0x81ea0d8)