FreeTDS Development Group

["Robert Dunkley" <Robert AT saq.co.uk>]

I'm seeing this error as soon as I put PowerDNS under any real load,
I've tried Stable 0.82 and the 0.83 build from last week but the result
is the same, I get that error after about 30 seconds of heavy traffic.
Initially I thought it was a PowerDNS/Open DBX issue (As shown in the
email below) but it seems the second error is FreeTDS specific.

Also shown below is a small extract from the FreeTDS log (The log is
huge). Does anyone know what causes this error? Is it a bug or some sort
of configuration issue?


Thanks,

Rob




-----Original Message-----
From: Robert Dunkley 
Sent: 25 August 2010 15:34
To: 'pdns-users AT mailman.powerdns.com'
Cc: 'libopendbx-devel AT lists.sourceforge.net'
Subject: OpenDBX + PowerDNS - Unable to execute query - Attempt to
initiate a new Adaptive Server operation 

Hi Everyone,


I'm load testing PowerDNS with OpenDBX (Using MSSQL) backend server with
Dnsperf. Unless I restrict the testing to about 100 queries per second
or less I start getting a much higher than expected number of failed dns
responses and the entries like the one below keep appearing in the log:

Aug 25 15:28:28 ns02 pdns[16430]: [OpendbxBackend] execStmt: Unable to
execute query - Attempt to initiate a new Adaptive Server operation with
results pending, Success
Aug 25 15:28:28 ns02 pdns[16430]: Database module reported condition
which prevented lookup (Error: DB statement failed) sending out servfail

Does anyone know what might be cauasing this? (Load on the MSSQL server
is a bit erratic but averaging less than 3% with lots of RAM spare).


Thanks,

Rob


util.c:162:Changed query state from PENDING to READING
token.c:510:processing result tokens.  marker is  fd(DONE)
token.c:2201:tds_process_end: more_results = 0
                was_cancelled = 0
                error = 0
                done_count_valid = 1
token.c:2217:tds_process_end() state set to TDS_IDLE
util.c:162:Changed query state from READING to IDLE
token.c:2232:                rows_affected = 0
util.c:110:logic error: cannot change query state from IDLE to PENDING
dblib.c:1630:dbresults() tds_process_tokens returned 1 (TDS_SUCCEED),
                        result_type TDS_DONE_RESULT
dblib.c:1657:dbresults(): dbresults_state is 1 (_DB_RES_RESULTSET_EMPTY)
dblib.c:1587:dbresults returning 1 (SUCCEED)
dblib.c:3960:dbcmdrow(0x1beaba50)
dblib.c:1745:dbnumcols(0x1beaba50)
dblib.c:2741:dbcoltype(0x1beaba50, 1)
dblib.c:2741:dbcoltype(0x1beaba50, 2)
dblib.c:2741:dbcoltype(0x1beaba50, 3)
dblib.c:2741:dbcoltype(0x1beaba50, 4)
dblib.c:2741:dbcoltype(0x1beaba50, 5)
dblib.c:2741:dbcoltype(0x1beaba50, 6)
dblib.c:1948:dbnextrow(0x1beaba50)
dblib.c:1961:dbnextrow() dbresults_state = 3 (_DB_RES_NEXT_RESULT)
dblib.c:1966:leaving dbnextrow() returning -2 (NO_MORE_ROWS)
dblib.c:1948:dbnextrow(0x1beaba50)
dblib.c:1961:dbnextrow() dbresults_state = 3 (_DB_RES_NEXT_RESULT)
dblib.c:1966:leaving dbnextrow() returning -2 (NO_MORE_ROWS)
dblib.c:1599:dbresults(0x1beaba50)
dblib.c:1608:dbresults: dbresults_state is 3 (_DB_RES_NEXT_RESULT)
token.c:495:tds_process_tokens(0x1beac370, 0x4596efe4, 0x4596efe0,
0x6914)
token.c:498:tds_process_tokens() state is COMPLETED
dblib.c:1630:dbresults() tds_process_tokens returned 2
(TDS_NO_MORE_RESULTS),
                        result_type TDS_DONE_RESULT
dblib.c:1587:dbresults returning 2 (NO_MORE_RESULTS)
dblib.c:6045:dbsafestr(0x1beaba50, addons.mozilla.org, 18,
media.fimnetwork.com, 512, 0)
dblib.c:1243:dbcmd(0x1beaba50, SELECT r."domain_id", r."name", r."type",
r."ttl", r."prio", r."content" FROM "records" r WHERE
r."name"='addons.mozilla.org')
dblib.c:1250:dbcmd() bufsz = 128
dblib.c:5727:dbfreebuf(0x1beaba50)
dblib.c:6722:dbsqlsend(0x1beaba50)
mem.c:563:tds_free_all_results()
util.c:162:Changed query state from IDLE to QUERYING
write.c:136:tds_put_string converting 125 bytes of "SELECT
r."domain_id", r."name", r."type", r."ttl", r."prio", r."content" FROM
"records" r WHERE r."name"='addons.mozilla.org'"
write.c:164:tds_put_string wrote 250 bytes
util.c:162:Changed query state from QUERYING to PENDING
net.c:779:Sending packet
0000 01 01 01 02 00 00 01 00-53 00 45 00 4c 00 45 00 |........ S.E.L.E.|
0010 43 00 54 00 20 00 72 00-2e 00 22 00 64 00 6f 00 |C.T. .r. ..".d.o.|
0020 6d 00 61 00 69 00 6e 00-5f 00 69 00 64 00 22 00 |m.a.i.n. _.i.d.".|
0030 2c 00 20 00 72 00 2e 00-22 00 6e 00 61 00 6d 00 |,. .r... ".n.a.m.|
0040 65 00 22 00 2c 00 20 00-72 00 2e 00 22 00 74 00 |e.".,. . r...".t.|
0050 79 00 70 00 65 00 22 00-2c 00 20 00 72 00 2e 00 |y.p.e.". ,. .r...|
0060 22 00 74 00 74 00 6c 00-22 00 2c 00 20 00 72 00 |".t.t.l. ".,. .r.|
0070 2e 00 22 00 70 00 72 00-69 00 6f 00 22 00 2c 00 |..".p.r. i.o.".,.|
0080 20 00 72 00 2e 00 22 00-63 00 6f 00 6e 00 74 00 | .r...". c.o.n.t.|
0090 65 00 6e 00 74 00 22 00-20 00 46 00 52 00 4f 00 |e.n.t.".  .F.R.O.|
00a0 4d 00 20 00 22 00 72 00-65 00 63 00 6f 00 72 00 |M. .".r. e.c.o.r.|
00b0 64 00 73 00 22 00 20 00-72 00 20 00 57 00 48 00 |d.s.". . r. .W.H.|
00c0 45 00 52 00 45 00 20 00-72 00 2e 00 22 00 6e 00 |E.R.E. . r...".n.|
00d0 61 00 6d 00 65 00 22 00-3d 00 27 00 61 00 64 00 |a.m.e.". =.'.a.d.|
00e0 64 00 6f 00 6e 00 73 00-2e 00 6d 00 6f 00 7a 00 |d.o.n.s. ..m.o.z.|
00f0 69 00 6c 00 6c 00 61 00-2e 00 6f 00 72 00 67 00 |i.l.l.a. ..o.r.g.|
0100 27 00                  -                        |'.|

dblib.c:6846:dbpoll(0x1beaba50, -1, 0x4596f028, 0x4596f034)
dblib.c:6851:UNIMPLEMENTED dbpoll()
dblib.c:4532:dbsqlok(0x1beaba50)
net.c:592:Received header
0000 04 01 00 8d 00 3a 01 00-                        |.....:..|

net.c:671:Received packet
0000 81 06 00 00 00 08 00 38-09 64 00 6f 00 6d 00 61 |.......8 .d.o.m.a|
0010 00 69 00 6e 00 5f 00 69-00 64 00 00 00 08 00 a7 |.i.n._.i .d......|
0020 ff 00 09 04 d0 00 34 04-6e 00 61 00 6d 00 65 00 |......4. n.a.m.e.|
0030 00 00 08 00 a7 06 00 09-04 d0 00 34 04 74 00 79 |........ ...4.t.y|
0040 00 70 00 65 00 00 00 09-00 26 04 03 74 00 74 00 |.p.e.... .&..t.t.|
0050 6c 00 00 00 09 00 26 04-04 70 00 72 00 69 00 6f |l.....&. .p.r.i.o|
0060 00 00 00 08 00 a7 ff 00-09 04 d0 00 34 07 63 00 |........ ....4.c.|
0070 6f 00 6e 00 74 00 65 00-6e 00 74 00 fd 10 00 c1 |o.n.t.e. n.t.....|
0080 00 00 00 00 00         -                        |.....|

dblib.c:4556:dbsqlok() exits on result token 0x81
dblib.c:1599:dbresults(0x1beaba50)
dblib.c:1608:dbresults: dbresults_state is 0 (_DB_RES_INIT)
token.c:495:tds_process_tokens(0x1beac370, 0x4596efe4, 0x4596efe0,
0x6914)
util.c:162:Changed query state from PENDING to READING
token.c:510:processing result tokens.  marker is  81(TDS7_RESULT)
token.c:1520:processing TDS7 result metadata.
mem.c:563:tds_free_all_results()
token.c:1544:set current_results (6 columns) to tds->res_info
token.c:1555:setting up column 0
token.c:1490:tds7_get_data_info:
        colname = domain_id (9 bytes)
        type = 56 (int)
        server's type = 56 (int)
        column_varint_size = 0
        column_size = 4 (4 on server)
token.c:1555:setting up column 1
token.c:3294:adjust_character_column_size:
        Server charset: CP1252
        Server column_size: 255
        Client charset: ISO-8859-1
        Client column_size: 255
token.c:1490:tds7_get_data_info:
        colname = name (4 bytes)
        type = 39 (varchar)
        server's type = 167 (xvarchar)
        column_varint_size = 2
        column_size = 255 (255 on server)
token.c:1555:setting up column 2
token.c:3294:adjust_character_column_size:
        Server charset: CP1252
        Server column_size: 6
        Client charset: ISO-8859-1
        Client column_size: 6
token.c:1490:tds7_get_data_info:
        colname = type (4 bytes)
        type = 39 (varchar)
        server's type = 167 (xvarchar)
        column_varint_size = 2
        column_size = 6 (6 on server)
token.c:1555:setting up column 3
token.c:1490:tds7_get_data_info:
        colname = ttl (3 bytes)
        type = 38 (integer-null)
        server's type = 38 (integer-null)
        column_varint_size = 1
        column_size = 4 (4 on server)
token.c:1555:setting up column 4
token.c:1490:tds7_get_data_info:
        colname = prio (4 bytes)
        type = 38 (integer-null)
        server's type = 38 (integer-null)
        column_varint_size = 1
        column_size = 4 (4 on server)
token.c:1555:setting up column 5
token.c:3294:adjust_character_column_size:
        Server charset: CP1252
        Server column_size: 255
        Client charset: ISO-8859-1
        Client column_size: 255
token.c:1490:tds7_get_data_info:
        colname = content (7 bytes)
        type = 39 (varchar)
        server's type = 167 (xvarchar)
        column_varint_size = 2
        column_size = 255 (255 on server)
util.c:162:Changed query state from READING to PENDING
dblib.c:1630:dbresults() tds_process_tokens returned 1 (TDS_SUCCEED),
                        result_type TDS_ROWFMT_RESULT
token.c:495:tds_process_tokens(0x1beac370, 0x4596efe4, 0x4596efe0,
0x6914)
util.c:162:Changed query state from PENDING to READING
token.c:510:processing result tokens.  marker is  fd(DONE)
token.c:2201:tds_process_end: more_results = 0
                was_cancelled = 0
                error = 0
                done_count_valid = 1
token.c:2217:tds_process_end() state set to TDS_IDLE
util.c:162:Changed query state from READING to IDLE
token.c:2232:                rows_affected = 0
util.c:110:logic error: cannot change query state from IDLE to PENDING
dblib.c:1630:dbresults() tds_process_tokens returned 1 (TDS_SUCCEED),
                        result_type TDS_DONE_RESULT
dblib.c:1657:dbresults(): dbresults_state is 1 (_DB_RES_RESULTSET_EMPTY)
dblib.c:1587:dbresults returning 1 (SUCCEED)
dblib.c:3960:dbcmdrow(0x1beaba50)
dblib.c:1745:dbnumcols(0x1beaba50)
dblib.c:2741:dbcoltype(0x1beaba50, 1)
dblib.c:2741:dbcoltype(0x1beaba50, 2)
dblib.c:2741:dbcoltype(0x1beaba50, 3)
dblib.c:2741:dbcoltype(0x1beaba50, 4)
dblib.c:2741:dbcoltype(0x1beaba50, 5)
dblib.c:2741:dbcoltype(0x1beaba50, 6)
dblib.c:1948:dbnextrow(0x1beaba50)
dblib.c:1961:dbnextrow() dbresults_state = 3 (_DB_RES_NEXT_RESULT)
dblib.c:1966:leaving dbnextrow() returning -2 (NO_MORE_ROWS)
dblib.c:1948:dbnextrow(0x1beaba50)
dblib.c:1961:dbnextrow() dbresults_state = 3 (_DB_RES_NEXT_RESULT)
dblib.c:1966:leaving dbnextrow() returning -2 (NO_MORE_ROWS)
dblib.c:1599:dbresults(0x1beaba50)
dblib.c:1608:dbresults: dbresults_state is 3 (_DB_RES_NEXT_RESULT)
token.c:495:tds_process_tokens(0x1beac370, 0x4596efe4, 0x4596efe0,
0x6914)
token.c:498:tds_process_tokens() state is COMPLETED
dblib.c:1630:dbresults() tds_process_tokens returned 2
(TDS_NO_MORE_RESULTS),
                        result_type TDS_DONE_RESULT
dblib.c:1587:dbresults returning 2 (NO_MORE_RESULTS)
dblib.c:6045:dbsafestr(0x1beaba50, mediaservices.myspace.com, 25,
addons.mozilla.org, 512, 0)
dblib.c:1243:dbcmd(0x1beaba50, SELECT r."domain_id", r."name", r."type",
r."ttl", r."prio", r."content" FROM "records" r WHERE
r."name"='mediaservices.myspace.com')
dblib.c:1250:dbcmd() bufsz = 126
dblib.c:5727:dbfreebuf(0x1beaba50)
dblib.c:6722:dbsqlsend(0x1beaba50)
mem.c:563:tds_free_all_results()
util.c:162:Changed query state from IDLE to QUERYING
write.c:136:tds_put_string converting 132 bytes of "SELECT
r."domain_id", r."name", r."type", r."ttl", r."prio", r."content" FROM
"records" r WHERE r."name"='mediaservices.myspace.com'"
write.c:136:tds_put_string converting 4 bytes of "com'"
write.c:164:tds_put_string wrote 264 bytes
util.c:162:Changed query state from QUERYING to PENDING
net.c:779:Sending packet
0000 01 01 01 10 00 00 01 00-53 00 45 00 4c 00 45 00 |
[root@ns01 tmp]# tail freetds.log
dblib.c:6722:dbsqlsend(0x1beaba50)
token.c:495:tds_process_tokens(0x1beac370, 0x4596ee2c, (nil), 0x2282a)
util.c:162:Changed query state from PENDING to READING
token.c:510:processing result tokens.  marker is  d1(ROW)
token.c:621:tds_process_tokens::SET_RETURN stopping on current token
util.c:162:Changed query state from READING to PENDING
dblib.c:7782:dbperror(0x1beaba50, 20019, 0)
dblib.c:7835:20019: "Attempt to initiate a new Adaptive Server operation
with results pending"
dblib.c:5627:dbgetuserdata(0x1beaba50)
dblib.c:7856:"Attempt to initiate a new Adaptive Server operation with
results pending", client returns 2 (INT_CANCEL)