Attempt to initiate a new Adaptive Server operation with results pending", client returns 2 (INT_CANCEL)
"Robert Dunkley" <[email protected]>
| Newsgroups | gmane.comp.db.tds.freetds |
|---|---|
| Message-ID | <C1EAC9C5E752D24C968FF091D446D823857E89@ALTERNATEREALIT> |
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: '[email protected]' Cc: '[email protected]' 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)