Bug 534 - IXFR query loop
IXFR query loop
Status: RESOLVED FIXED
Product: NSD
Classification: Unclassified
Component: NSD Code
4.0.x
Other Linux
: P5 normal
Assigned To: NSD team
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2013-11-03 20:18 CET by 335b7bb5b3dc
Modified: 2013-11-11 16:26 CET (History)
1 user (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description 335b7bb5b3dc 2013-11-03 20:18:59 CET
After upgrading a secondary NS to NSD 4.0.0, the master server came under IXFR query flood from the slave.

I have been able to reproduce it only once in a test setup. It doesn't fail reliably. Removing "UDP" from "request-xfr" works around the problem.

Upon "nsd-control start" on the slave, the master logs several hundred queries per second:

Nov  3 19:50:03 client 127.0.1.1#59464: query: example.com IN IXFR - (127.0.0.1)
Nov  3 19:50:03 client 127.0.1.1#51833: query: example.com IN IXFR - (127.0.0.1)
Nov  3 19:50:03 client 127.0.1.1#34663: query: example.com IN IXFR - (127.0.0.1)
[...]

I'll add more details if I can reproduce it again.


This is the config used in the test:

server:
        ip-address: 127.0.1.1

pattern:
        name: "common"
        outgoing-interface: 127.0.1.1

pattern:
        name: "local-bind"
        allow-notify: 127.0.0.1 NOKEY
        request-xfr: UDP 127.0.0.1 NOKEY
        include-pattern: "common"

zone:
        name: "example.com"
        zonefile: "example.com.zone"
        include-pattern: "local-bind"
Comment 1 335b7bb5b3dc 2013-11-03 20:31:20 CET
It works better with the query log on...

I can reproduce the problem with these steps and the config above:

1. remove nsd.db and xfrd.state (rm /var/lib/nsd/*)

2. nsd-control start
Nov  3 20:26:27 client 127.0.1.1#59111: query: example.com IN AXFR -T (127.0.0.1)
Nov  3 20:26:27 client 127.0.1.1#59111: transfer of 'example.com/IN': AXFR started
Nov  3 20:26:27 client 127.0.1.1#59111: transfer of 'example.com/IN': AXFR ended
Nov  3 20:26:27 nsd started (NSD 4.0.0), pid 21174
Nov  3 20:26:28 Zone example.com serial 0 is updated to 2.

3. nsd-control stop

4. nsd-control start
Nov  3 20:27:22 client 127.0.1.1#40852: query: example.com IN IXFR - (127.0.0.1)
Nov  3 20:27:22 client 127.0.1.1#50301: query: example.com IN IXFR - (127.0.0.1)
Nov  3 20:27:22 client 127.0.1.1#45728: query: example.com IN IXFR - (127.0.0.1)
Nov  3 20:27:22 client 127.0.1.1#45245: query: example.com IN IXFR - (127.0.0.1)
[...]
Comment 2 335b7bb5b3dc 2013-11-04 02:11:26 CET
Debug output:

setup SSL certificates
file rotation on (null) enabled
dropped user privileges, run as nsd
xfrd pre-startup
xfrd: adding example.com zone
xfrd zone example.com is activated, state 1
xfrd: started server 1 secondary zones
task procsync /tmp/nsd.27779.task.1 size 288
debian-wheezy-minimal nsd[27780]: zonefile example.com.zone does not exist
debian-wheezy-minimal nsd[27780]: nsd: add soa info for zone example.com.
debian-wheezy-minimal nsd[27780]: task procsync /tmp/nsd.27779.task.0 size 768
task remap /tmp/nsd.27779.task.0 size 768
xfrd: process SOAINFO example.com.
SOAINFO for example.com. 6
xfrd: zone example.com serial 6 from unknown source. refreshing
xfrd zone example.com is activated, state 1
debian-wheezy-minimal nsd[27780]: task remap /tmp/nsd.27779.task.1 size 288
xfrd zone example.com is activated, state 1
xfrd: read 1 zones from state file
xfrd startup
xfrd zone example.com activation
xfrd: zone example.com timeout
xfrd zone example.com make request round 0 mr 0 nx -1
sent query with ID 30978
xfrd: bind() 127.0.1.1 to udp socket
xfrd: bind() 127.0.1.1 to udp socket was successful
xfrd sent udp request for ixfr=6 for zone example.com to 127.0.0.1
xfrd: zone example.com event udp read
xfrd zone example.com is activated, state 1
xfrd: zone example.com read udp data
got query with ID 30978 and 30978 needed
xfrd: zone example.com got update indicating current serial
xfrd: zone example.com is ok
xfrd zone example.com activation
xfrd: zone example.com timeout
xfrd zone example.com make request round 0 mr 0 nx -1
sent query with ID 24561
xfrd: bind() 127.0.1.1 to udp socket
xfrd: bind() 127.0.1.1 to udp socket was successful
xfrd sent udp request for ixfr=6 for zone example.com to 127.0.0.1
xfrd: zone example.com event udp read
xfrd zone example.com is activated, state 0
xfrd: zone example.com read udp data
got query with ID 24561 and 24561 needed
xfrd: zone example.com got update indicating current serial
xfrd: zone example.com is ok
xfrd zone example.com activation
xfrd: zone example.com timeout
xfrd zone example.com make request round 0 mr 0 nx -1
sent query with ID 17740
xfrd: bind() 127.0.1.1 to udp socket
xfrd: bind() 127.0.1.1 to udp socket was successful
xfrd sent udp request for ixfr=6 for zone example.com to 127.0.0.1
xfrd: zone example.com event udp read
xfrd zone example.com is activated, state 0
xfrd: zone example.com read udp data
got query with ID 17740 and 17740 needed
xfrd: zone example.com got update indicating current serial
xfrd: zone example.com is ok
xfrd zone example.com activation
xfrd: zone example.com timeout
xfrd zone example.com make request round 0 mr 0 nx -1
sent query with ID 32700
xfrd: bind() 127.0.1.1 to udp socket
xfrd: bind() 127.0.1.1 to udp socket was successful
xfrd sent udp request for ixfr=6 for zone example.com to 127.0.0.1
xfrd: zone example.com event udp read
xfrd zone example.com is activated, state 0
xfrd: zone example.com read udp data
got query with ID 32700 and 32700 needed
xfrd: zone example.com got update indicating current serial
xfrd: zone example.com is ok
xfrd zone example.com activation
xfrd: zone example.com timeout
xfrd zone example.com make request round 0 mr 0 nx -1
sent query with ID 32745
xfrd: bind() 127.0.1.1 to udp socket
xfrd: bind() 127.0.1.1 to udp socket was successful
xfrd sent udp request for ixfr=6 for zone example.com to 127.0.0.1
xfrd: zone example.com event udp read
xfrd zone example.com is activated, state 0
xfrd: zone example.com read udp data
got query with ID 32745 and 32745 needed
xfrd: zone example.com got update indicating current serial
xfrd: zone example.com is ok
xfrd zone example.com activation
xfrd: zone example.com timeout
xfrd zone example.com make request round 0 mr 0 nx -1
sent query with ID 49489
xfrd: bind() 127.0.1.1 to udp socket
xfrd: bind() 127.0.1.1 to udp socket was successful
xfrd sent udp request for ixfr=6 for zone example.com to 127.0.0.1
xfrd: zone example.com event udp read
xfrd zone example.com is activated, state 0
xfrd: zone example.com read udp data
got query with ID 49489 and 49489 needed
xfrd: zone example.com got update indicating current serial
[...]
Comment 3 Wouter Wijngaards 2013-11-11 15:38:20 CET
Hi Anon,

Thank you for the detailed output, I'll see if I can reproduce this.

Best regards, Wouter
Comment 4 Wouter Wijngaards 2013-11-11 16:26:45 CET
Hi Anon,

I can reproduce the bug and this patch (also in our source svn) fixes
the issue.  (you can also fetch our svn trunk).

Thank you for the report

Best regards, Wouter


Index: xfrd.c
===================================================================
--- xfrd.c	(revision 4095)
+++ xfrd.c	(working copy)
@@ -707,7 +707,6 @@
 	if((event & EV_READ)) {
 		/* busy in udp transaction */
 		DEBUG(DEBUG_XFRD,1, (LOG_INFO, "xfrd: zone %s event udp read", zone->apex_str));
-		xfrd_set_refresh_now(zone);
 		xfrd_udp_read(zone);
 		return;
 	}