[Opendnssec-develop] Re: [OpenDNSSEC] #247: Hang signer processes after receiving several notifies in succession

Thu Jun 30 18:28:21 UTC 2011

On Thu, 30 Jun 2011, OpenDNSSEC wrote:

> From: OpenDNSSEC <owner-dnssec-trac at kirei.se>
> Cc: "opendnssec-develop at lists.opendnssec.org"
>     <opendnssec-develop at lists.opendnssec.org>
> Message-ID: <071.753682283f2a33d6247fe4f40cb49f8c at kirei.se>
> Date: Thu, 30 Jun 2011 14:55:21 +0200
> Subject: Re: [OpenDNSSEC] #247: Hang signer processes after receiving several
>     notifies in succession
> 
> #247: Hang signer processes after receiving several notifies in succession
> -----------------------------------+----------------------------------------
> Reporter:  goeran@…                |        Owner:  matthijs
>    Type:  defect                  |       Status:  accepted
> Priority:  major                   |    Component:  Signer
> Version:  1.3.0                   |   Resolution:
> Keywords:  signer, hang, notifies  |
> -----------------------------------+----------------------------------------
>
> Comment (by matthijs):
>
> I think this happens when notifies are coming in quicker than the signer
> can sign the zone. In the OpenDNSSEC-1.3 branch, I have committed a change
> (r5272) where the zone fetcher unlocks the axfr file before it kicks the
> signer daemon. This solved this issue for me.

Sounds reasonable.

>
> Could you try out r5272+ of the branch?

I was back at 1.2.1 and upgraded to 1.3.0 r5273.
After a couple of upgrade problems (soa s/n not incremented etc)
I was able to check if the notify-problem was resolved.
Unfortunately I don't think it is, at least not for me.

After receiving 2 notifies (of several, se below), both resulting in
an axfr, the signer process seems to endup consume cpu but never to
complete the signing operation. It also blocks signing of other zones.

[root at ns-test rc3]# ods-signer queue
It is now Thu Jun 30 20:16:34 2011
Working with task [sign] on zone itsnat.se

I have 9 tasks scheduled.
On Thu Jun 30 20:16:35 2011 I will [sign] zone 50.5.192.in-addr.arpa
On Thu Jun 30 20:19:44 2011 I will [sign] zone 16.129.in-addr.arpa
On Thu Jun 30 20:52:34 2011 I will [sign] zone chalmers.se
On Thu Jun 30 21:04:52 2011 I will [sign] zone chalmers.eu
On Thu Jun 30 21:05:06 2011 I will [sign] zone 120.36.192.in-addr.arpa
On Thu Jun 30 21:05:24 2011 I will [sign] zone gbg.sunet.se
On Thu Jun 30 21:06:39 2011 I will [sign] zone 2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa
On Thu Jun 30 21:07:00 2011 I will [sign] zone 224.36.192.in-addr.arpa
On Thu Jun 30 21:07:05 2011 I will [sign] zone 225.36.192.in-addr.arpa

It is now Thu Jun 30 20:27:22 2011
Working with task [sign] on zone itsnat.se
Working with task [sign] on zone 50.5.192.in-addr.arpa
Working with task [sign] on zone chalmers.eu
Working with task [sign] on zone 16.129.in-addr.arpa

I have 6 tasks scheduled.
On Thu Jun 30 20:52:34 2011 I will [sign] zone chalmers.se
On Thu Jun 30 21:05:06 2011 I will [sign] zone 120.36.192.in-addr.arpa
On Thu Jun 30 21:05:24 2011 I will [sign] zone gbg.sunet.se
On Thu Jun 30 21:06:39 2011 I will [sign] zone 2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa
On Thu Jun 30 21:07:00 2011 I will [sign] zone 224.36.192.in-addr.arpa
On Thu Jun 30 21:07:05 2011 I will [sign] zone 225.36.192.in-addr.arpa

>From the NS sending the notifies:

Jun 30 20:08:14 ns-test named[3604]: general: info: received control channel command 'reload itsnat.se'
Jun 30 20:08:14 ns-test named[3604]: general: info: zone itsnat.se/IN: loaded serial 2011063008
Jun 30 20:08:14 ns-test named[3604]: notify: info: zone itsnat.se/IN: sending notifies (serial 2011063008)
Jun 30 20:08:14 ns-test named[3604]: xfer-out: info: client 127.0.0.1#41663: transfer of 'itsnat.se/IN': AXFR started
Jun 30 20:08:14 ns-test named[3604]: xfer-out: info: client 127.0.0.1#41663: transfer of 'itsnat.se/IN': AXFR ended
Jun 30 20:08:33 ns-test named[3604]: general: info: received control channel command 'reload itsnat.se'
Jun 30 20:08:34 ns-test named[3604]: general: info: zone itsnat.se/IN: loaded serial 2011063009
Jun 30 20:08:34 ns-test named[3604]: notify: info: zone itsnat.se/IN: sending notifies (serial 2011063009)
Jun 30 20:08:34 ns-test named[3604]: xfer-out: info: client 127.0.0.1#41664: transfer of 'itsnat.se/IN': AXFR started
Jun 30 20:08:34 ns-test named[3604]: xfer-out: info: client 127.0.0.1#41664: transfer of 'itsnat.se/IN': AXFR ended
Jun 30 20:08:38 ns-test named[3604]: general: info: received control channel command 'reload itsnat.se'
Jun 30 20:08:38 ns-test named[3604]: general: info: zone itsnat.se/IN: loaded serial 2011063010
Jun 30 20:08:39 ns-test named[3604]: notify: info: zone itsnat.se/IN: sending notifies (serial 2011063010)
Jun 30 20:08:50 ns-test named[3604]: general: info: received control channel command 'reload itsnat.se'
Jun 30 20:08:51 ns-test named[3604]: general: info: zone itsnat.se/IN: loaded serial 2011063011
Jun 30 20:08:51 ns-test named[3604]: notify: info: zone itsnat.se/IN: sending notifies (serial 2011063011)
Jun 30 20:09:03 ns-test named[3604]: general: info: received control channel command 'reload itsnat.se'
Jun 30 20:09:04 ns-test named[3604]: general: info: zone itsnat.se/IN: loaded serial 2011063012
Jun 30 20:09:04 ns-test named[3604]: notify: info: zone itsnat.se/IN: sending notifies (serial 2011063012)

>From opendnssec:
Jun 30 20:08:14 ns-test ods-signerd: zone fetcher received NOTIFY for zone itsnat.se
Jun 30 20:08:15 ns-test ods-signerd: zone fetcher transferred zone itsnat.se serial 2011063008 successfully
Jun 30 20:08:34 ns-test ods-signerd: zone fetcher received NOTIFY for zone itsnat.se
Jun 30 20:08:34 ns-test ods-signerd: zone fetcher transferred zone itsnat.se serial 2011063009 successfully

>
> -- 
> Ticket URL: <http://trac.opendnssec.org/ticket/247#comment:3>
> OpenDNSSEC <http://www.opendnssec.org/>
> OpenDNSSEC

 			/ Göran Bengtson
 			  Chalmers University of Technology