[Pdns-dev] Problem with slave transfers

Fri Oct 12 11:31:13 CEST 2012

Hello list,

On Monday we experienced a problem with our primary nameserver.
The powerdns process stopped with the transfer of slave domains. The "queued for AXFR" counter kept rising.

After a restart the problem was temporarily solved. Yesterday the problem occurred again. And this morning, after restart, again within 20 minutes after restart.

10:33:37 is restart,  10:53:55 s last axfr activity

Some logs from axfr action after restart:

Queued for axfr counter right before restart and after:

Oct 12 10:30:11 ns2 pdns[4579]: 43 slave domains need checking, 5 queued for AXFR
Oct 12 10:31:19 ns2 pdns[4579]: 44 slave domains need checking, 5 queued for AXFR
Oct 12 10:32:27 ns2 pdns[4579]: 51 slave domains need checking, 5 queued for AXFR
Oct 12 10:33:30 ns2 pdns[16059]: 52 slave domains need checking, 0 queued for AXFR
Oct 12 10:34:37 ns2 pdns[16059]: 48 slave domains need checking, 0 queued for AXFR
Oct 12 10:35:45 ns2 pdns[16059]: 45 slave domains need checking, 0 queued for AXFR

After last attempt:

Oct 12 10:51:32 ns2 pdns[16059]: 51 slave domains need checking, 0 queued for AXFR
Oct 12 10:52:40 ns2 pdns[16059]: 47 slave domains need checking, 0 queued for AXFR
Oct 12 10:53:48 ns2 pdns[16059]: 45 slave domains need checking, 1 queued for AXFR 
Oct 12 10:54:56 ns2 pdns[16059]: 42 slave domains need checking, 2 queued for AXFR
Oct 12 10:56:04 ns2 pdns[16059]: 47 slave domains need checking, 2 queued for AXFR
Oct 12 10:57:12 ns2 pdns[16059]: 42 slave domains need checking, 2 queued for AXFR
.
.
.
Oct 12 11:15:26 ns2 pdns[16059]: 46 slave domains need checking, 2 queued for AXFR
Oct 12 11:16:34 ns2 pdns[16059]: 42 slave domains need checking, 2 queued for AXFR
Oct 12 11:17:43 ns2 pdns[16059]: 49 slave domains need checking, 2 queued for AXFR

Loglines with axfr activity:

root at ns2:~# grep "transaction started" /var/log/syslog
Oct 12 10:33:37 ns2 pdns[16059]: AXFR started for 'domain1', transaction started
Oct 12 10:33:37 ns2 pdns[16059]: AXFR started for 'domain2', transaction started
Oct 12 10:33:37 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:33:37 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:33:37 ns2 pdns[16059]: AXFR started for 'domain5', transaction started
Oct 12 10:34:45 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:35:36 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:35:53 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:36:44 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:37:01 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:37:52 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:38:09 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:39:00 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:39:18 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:40:09 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:40:26 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:41:17 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:41:34 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:42:25 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:42:42 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:43:33 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:43:51 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:44:42 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:44:56 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:45:47 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:46:04 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:46:55 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:47:08 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:47:59 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:48:17 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:49:08 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:49:24 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:50:15 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:50:32 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:51:23 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:51:39 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:52:30 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:52:47 ns2 pdns[16059]: AXFR started for 'domain4', transaction started

Domain1 is commited correct
Domain2 is commited correct
Domain5 is commited correct

Domain3 fails repeatedly

Oct 12 10:52:30 ns2 pdns[16059]: Initiating transfer of 'domain3' from remote 'ip-address'
Oct 12 10:52:30 ns2 pdns[16059]: AXFR started for 'domain3', transaction started
Oct 12 10:52:30 ns2 pdns[16059]: Unable to AXFR zone 'domain3' from remote 'ip-address' (resolver): Remote nameserver closed TCP connection
Oct 12 10:52:30 ns2 pdns[16059]: Aborting possible open transaction for domain 'domain3' AXFR
Oct 12 10:52:47 ns2 pdns[16059]: Domain domain3 is stale, master serial 2012101008, our serial 2012073102

Domain4 fails repeatedly

root at ns2:~# grep domain4 /var/log/syslog
Oct 12 10:33:37 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:33:37 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:33:37 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:33:37 ns2 pdns[16059]: Remote ip-address2 tried to sneak in out-of-zone data 'ns1.dm-interface.nl'|A during AXFR of zone 'domain4', ignoring
Oct 12 10:33:37 ns2 pdns[16059]: Remote ip-address2 tried to sneak in out-of-zone data 'ns2.nxs.nl'|A during AXFR of zone 'domain4', ignoring
Oct 12 10:33:37 ns2 pdns[16059]: Remote ip-address2 tried to sneak in out-of-zone data 'ns3.nxs.nl'|A during AXFR of zone 'domain4', ignoring
Oct 12 10:34:45 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:34:45 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:34:45 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:35:53 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:35:53 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:35:53 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:37:01 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:37:01 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:37:01 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:38:09 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:38:09 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:38:09 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:39:18 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:39:18 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:39:18 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:40:26 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:40:26 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:40:26 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:41:34 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:41:34 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:41:34 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:42:42 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:42:42 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:42:42 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:43:51 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:43:51 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:43:51 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:44:56 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:44:56 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:44:56 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:46:04 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:46:04 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:46:04 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:47:08 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:47:08 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:47:08 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:48:16 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:48:16 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:48:17 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:49:24 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:49:24 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:49:24 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:50:32 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:50:32 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:50:32 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:51:39 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:51:39 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:51:39 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:52:47 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291
Oct 12 10:52:47 ns2 pdns[16059]: Initiating transfer of 'domain4' from remote 'ip-address2'
Oct 12 10:52:47 ns2 pdns[16059]: AXFR started for 'domain4', transaction started
Oct 12 10:53:37 ns2 pdns[16059]: Remote ip-address2 tried to sneak in out-of-zone data 'ns3.nxs.nl'|A during AXFR of zone 'domain4', ignoring
Oct 12 10:53:37 ns2 pdns[16059]: Remote ip-address2 tried to sneak in out-of-zone data 'ns1.dm-interface.nl'|A during AXFR of zone 'domain4', ignoring
Oct 12 10:53:37 ns2 pdns[16059]: Remote ip-address2 tried to sneak in out-of-zone data 'ns2.nxs.nl'|A during AXFR of zone 'domain4', ignoring
Oct 12 10:53:55 ns2 pdns[16059]: Domain domain4 is stale, master serial 2011092310, our serial 2011092291

dig -t axfr domain4 @ip-address2 sometimes works (43msec), sometimes it stops somewhere in the middle of the zone.

It looks to me as if the number of available axfr transactions is limited and not cleaned properly.

We are running PowerDNS 3.1.

Sorry for the lengthy email.
I'm willing to provide more information if needed.

Kind regards,

Coen Rosdorff
System administrator

Nxs infrastructure services