[Opendnssec-develop] Re: [OpenDNSSEC] #262: Possible race condition causing CPU-bound loop in signerd?

Fri Oct 28 14:28:44 UTC 2011

On Fri, 28 Oct 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.1a56e1f49ebc562b8f5d2ba606f5f47d at kirei.se>
> Date: Fri, 28 Oct 2011 12:00:04 +0200
> Subject: Re: [OpenDNSSEC] #262: Possible race condition causing CPU-bound loop
>      in signerd?
> 
> #262: Possible race condition causing CPU-bound loop in signerd?
> -------------------------------+--------------------------------------------
> Reporter:  goeran@…            |        Owner:  matthijs
>    Type:  defect              |       Status:  accepted
> Priority:  major               |    Component:  Signer
> Version:  1.3.0               |   Resolution:
> Keywords:  CPU-bound loop      |
> -------------------------------+--------------------------------------------
>
> Comment (by matthijs):
>
> Hi,
>
> In the OpenDNSSEC-1.3 branch, revision 5821, I have added a mechanism that
> sends out an additional broadcast message to the drudgers, if the queue is
> full, but no items are removed anymore.
>
> http://trac.opendnssec.org/changeset/5821/branches/OpenDNSSEC-1.3/signer/src
>
> Could you try that patch?

I've installed the 5821 revision from the OpenDNSSEC-1.3 branch (or should
I use 1.3.2 release with only this patch?).

Comment below:

 	I must add that since my last input in this case, ODS has been running
 	without problem since October 4th. Rev. 5664 from the 1.3-branch.
 	That the problem comes and goes with irregular intervals has always
 	been the case. We did one small change in the environment on
 	October 4th.  We changed the NTPconfig to disallow time to step.
 	The system is a VMWare guest so the "load-balancer" in VMware (DRS) may
 	move the guest from one host to another, an operation that is "almost"
 	transparent to the guest, but the clock often drops some fraction of a
 	second causing ntp with to original config to step the clock 0.1s or
 	so. However, we don't think this was the cause since  logs indicate
 	that the VMware load-balancer started to move the guest after it
 	got stuck in the CPU-loop. I've now change the ntp config back to
 	its previous version.

 	More interesting is that after starting the Rev. 5821 code a
 	ods-signer sign --all entries in the log (attached below)
 	indicate that your added code actually was triggered....

 			/ Göran Bengtson
 			  ITService Nät
 			  Chalmers

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

log file after restart with the new code:

Oct 28 15:59:51 ns-test ods-enforcerd: HSM opened successfully.
Oct 28 15:59:51 ns-test ods-enforcerd: Reading config "/usr/local/etc/opendnssec/conf.xml"
Oct 28 15:59:51 ns-test ods-enforcerd: Reading config schema "/usr/local/share/opendnssec/conf.rng"
Oct 28 15:59:51 ns-test ods-enforcerd: Communication Interval: 3600
Oct 28 15:59:51 ns-test ods-enforcerd: Using command: /usr/local/bin/ds-submit to submit DS records
Oct 28 15:59:51 ns-test ods-enforcerd: SQLite database set to: /var/opendnssec/kasp.db
Oct 28 15:59:51 ns-test ods-enforcerd: Log User set to: local4
Oct 28 15:59:51 ns-test ods-enforcerd: Switched log facility to: local4
Oct 28 15:59:51 ns-test ods-enforcerd: Connecting to Database...
Oct 28 15:59:51 ns-test ods-enforcerd: Policy default found.
Oct 28 15:59:51 ns-test ods-enforcerd: Key sharing is Off.
Oct 28 15:59:51 ns-test ods-enforcerd: Purging keys...
Oct 28 15:59:51 ns-test ods-enforcerd: Policy itsnat found.
Oct 28 15:59:51 ns-test ods-enforcerd: Key sharing is Off.
Oct 28 15:59:51 ns-test ods-enforcerd: Purging keys...
Oct 28 15:59:51 ns-test ods-enforcerd: Policy csnet found.
Oct 28 15:59:51 ns-test ods-enforcerd: Key sharing is Off.
Oct 28 15:59:51 ns-test ods-enforcerd: Purging keys...
Oct 28 15:59:51 ns-test ods-enforcerd: zonelist filename set to /usr/local/etc/opendnssec/zonelist.xml.
Oct 28 15:59:51 ns-test ods-enforcerd: Zone itsnat.se found.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy for itsnat.se set to itsnat.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy itsnat found in DB.
Oct 28 15:59:51 ns-test ods-enforcerd: Config will be output to /var/opendnssec/signconf/itsnat.se.xml.
Oct 28 15:59:51 ns-test ods-enforcerd: No change to: /var/opendnssec/signconf/itsnat.se.xml
Oct 28 15:59:51 ns-test ods-enforcerd: Zone chalmers.se found.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy for chalmers.se set to default.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy default found in DB.
Oct 28 15:59:51 ns-test ods-enforcerd: Config will be output to /var/opendnssec/signconf/chalmers.se.xml.
Oct 28 15:59:51 ns-test ods-enforcerd: No change to: /var/opendnssec/signconf/chalmers.se.xml
Oct 28 15:59:51 ns-test ods-enforcerd: Zone chalmers.eu found.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy for chalmers.eu set to default.
Oct 28 15:59:51 ns-test ods-enforcerd: Config will be output to /var/opendnssec/signconf/chalmers.eu.xml.
Oct 28 15:59:51 ns-test ods-enforcerd: No change to: /var/opendnssec/signconf/chalmers.eu.xml
Oct 28 15:59:51 ns-test ods-enforcerd: Zone 16.129.in-addr.arpa found.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy for 16.129.in-addr.arpa set to default.
Oct 28 15:59:51 ns-test ods-enforcerd: Config will be output to /var/opendnssec/signconf/16.129.in-addr.arpa.xml.
Oct 28 15:59:51 ns-test ods-enforcerd: No change to: /var/opendnssec/signconf/16.129.in-addr.arpa.xml
Oct 28 15:59:51 ns-test ods-enforcerd: Zone 50.5.192.in-addr.arpa found.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy for 50.5.192.in-addr.arpa set to csnet.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy csnet found in DB.
Oct 28 15:59:51 ns-test ods-enforcerd: Config will be output to /var/opendnssec/signconf/50.5.192.in-addr.arpa.xml.
Oct 28 15:59:51 ns-test ods-enforcerd: No change to: /var/opendnssec/signconf/50.5.192.in-addr.arpa.xml
Oct 28 15:59:51 ns-test ods-enforcerd: Zone gbg.sunet.se found.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy for gbg.sunet.se set to default.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy default found in DB.
Oct 28 15:59:51 ns-test ods-enforcerd: Config will be output to /var/opendnssec/signconf/gbg.sunet.se.xml.
Oct 28 15:59:51 ns-test ods-enforcerd: No change to: /var/opendnssec/signconf/gbg.sunet.se.xml
Oct 28 15:59:51 ns-test ods-enforcerd: Zone 2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa found.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy for 2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa set to default.
Oct 28 15:59:51 ns-test ods-enforcerd: Config will be output to /var/opendnssec/signconf/2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa.xml.
Oct 28 15:59:51 ns-test ods-enforcerd: No change to: /var/opendnssec/signconf/2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa.xml
Oct 28 15:59:51 ns-test ods-enforcerd: Zone 224.36.192.in-addr.arpa found.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy for 224.36.192.in-addr.arpa set to default.
Oct 28 15:59:51 ns-test ods-enforcerd: Config will be output to /var/opendnssec/signconf/224.36.192.in-addr.arpa.xml.
Oct 28 15:59:51 ns-test ods-enforcerd: No change to: /var/opendnssec/signconf/224.36.192.in-addr.arpa.xml
Oct 28 15:59:51 ns-test ods-enforcerd: Zone 225.36.192.in-addr.arpa found.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy for 225.36.192.in-addr.arpa set to default.
Oct 28 15:59:51 ns-test ods-enforcerd: Config will be output to /var/opendnssec/signconf/225.36.192.in-addr.arpa.xml.
Oct 28 15:59:51 ns-test ods-enforcerd: No change to: /var/opendnssec/signconf/225.36.192.in-addr.arpa.xml
Oct 28 15:59:51 ns-test ods-enforcerd: Zone 120.36.192.in-addr.arpa found.
Oct 28 15:59:51 ns-test ods-enforcerd: Policy for 120.36.192.in-addr.arpa set to default.
Oct 28 15:59:51 ns-test ods-enforcerd: Config will be output to /var/opendnssec/signconf/120.36.192.in-addr.arpa.xml.
Oct 28 15:59:51 ns-test ods-enforcerd: No change to: /var/opendnssec/signconf/120.36.192.in-addr.arpa.xml
Oct 28 15:59:51 ns-test ods-enforcerd: Disconnecting from Database...
Oct 28 15:59:51 ns-test ods-enforcerd: Sleeping for 3600 seconds.
Oct 28 15:59:52 ns-test ods-signerd: zone fetcher started
Oct 28 15:59:52 ns-test ods-signerd: [engine] signer started
Oct 28 15:59:52 ns-test ods-signerd: zone fetcher zone itsnat.se is already up to date, serial is 2011102805
Oct 28 15:59:52 ns-test ods-signerd: zone fetcher zone chalmers.se is already up to date, serial is 2011102805
Oct 28 15:59:52 ns-test ods-signerd: zone fetcher zone chalmers.eu is already up to date, serial is 2011063005
Oct 28 15:59:52 ns-test ods-signerd: zone fetcher zone 16.129.in-addr.arpa is already up to date, serial is 2011102805
Oct 28 15:59:52 ns-test ods-signerd: zone fetcher zone 50.5.192.in-addr.arpa is already up to date, serial is 2011070712
Oct 28 15:59:52 ns-test ods-signerd: zone fetcher zone gbg.sunet.se is already up to date, serial is 2011051814
Oct 28 15:59:52 ns-test ods-signerd: zone fetcher zone 2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa is already up to date, serial is 2011101801
Oct 28 15:59:52 ns-test ods-signerd: zone fetcher zone 224.36.192.in-addr.arpa is already up to date, serial is 2011051814
Oct 28 15:59:52 ns-test ods-signerd: zone fetcher zone 225.36.192.in-addr.arpa is already up to date, serial is 2011051814
Oct 28 15:59:52 ns-test ods-signerd: zone fetcher zone 120.36.192.in-addr.arpa is already up to date, serial is 2011071301
Oct 28 16:00:14 ns-test ods-auditor[7556]: Auditor started
Oct 28 16:00:14 ns-test ods-auditor[7556]: Auditor starting on 50.5.192.in-addr.arpa
Oct 28 16:00:14 ns-test ods-auditor[7556]: Auditing 50.5.192.in-addr.arpa zone : NSEC3 SIGNED
Oct 28 16:00:47 ns-test ods-auditor[7556]: SOA differs : from 2011070712 to 2011102815
Oct 28 16:00:48 ns-test ods-auditor[7556]: Finished auditing 50.5.192.in-addr.arpa zone
Oct 28 16:00:48 ns-test my-reload[7572]: Start processing 50.5.192.in-addr.arpa
Oct 28 16:00:48 ns-test my-reload[7572]: End processing 50.5.192.in-addr.arpa
Oct 28 16:00:48 ns-test ods-signerd: [STATS] 50.5.192.in-addr.arpa RR[count=0 time=0(sec)] NSEC3[count=0 time=0(sec)] RRSIG[new=7 reused=511 time=0(sec) avg=0(sig/sec)] AUDIT[time=34(sec)] TOTAL[time=34(sec)] 
Oct 28 16:02:39 ns-test ods-auditor[7602]: Auditor started
Oct 28 16:02:39 ns-test ods-auditor[7602]: Auditor starting on 225.36.192.in-addr.arpa
Oct 28 16:02:39 ns-test ods-auditor[7602]: Auditing 225.36.192.in-addr.arpa zone : NSEC3 SIGNED
Oct 28 16:03:12 ns-test ods-auditor[7602]: SOA differs : from 2011051814 to 2011102815
Oct 28 16:03:12 ns-test ods-auditor[7602]: Finished auditing 225.36.192.in-addr.arpa zone
Oct 28 16:03:12 ns-test my-reload[7612]: Start processing 225.36.192.in-addr.arpa
Oct 28 16:03:12 ns-test my-reload[7612]: End processing 225.36.192.in-addr.arpa
Oct 28 16:03:12 ns-test ods-signerd: [STATS] 225.36.192.in-addr.arpa RR[count=0 time=0(sec)] NSEC3[count=0 time=0(sec)] RRSIG[new=2 reused=515 time=0(sec) avg=0(sig/sec)] AUDIT[time=33(sec)] TOTAL[time=33(sec)] 
Oct 28 16:06:19 ns-test ods-auditor[7640]: Auditor started
Oct 28 16:06:19 ns-test ods-auditor[7640]: Auditor starting on 224.36.192.in-addr.arpa
Oct 28 16:06:19 ns-test ods-auditor[7640]: Auditing 224.36.192.in-addr.arpa zone : NSEC3 SIGNED
Oct 28 16:06:20 ns-test ods-auditor[7642]: Auditor started
Oct 28 16:06:22 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:24 ns-test last message repeated 32208 times
Oct 28 16:06:24 ns-test ods-auditor[7644]: Auditor started
Oct 28 16:06:24 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:24 ns-test last message repeated 11316 times
Oct 28 16:06:24 ns-test ods-auditor[7651]: Auditor started
Oct 28 16:06:24 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:24 ns-test last message repeated 13 times
Oct 28 16:06:24 ns-test ods-auditor[7644]: Auditor starting on 120.36.192.in-addr.arpa
Oct 28 16:06:24 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:24 ns-test last message repeated 13 times
Oct 28 16:06:24 ns-test ods-auditor[7644]: Auditing 120.36.192.in-addr.arpa zone : NSEC3 SIGNED
Oct 28 16:06:24 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:25 ns-test last message repeated 11558 times
Oct 28 16:06:24 ns-test ods-auditor[7646]: Auditor started
Oct 28 16:06:25 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:25 ns-test last message repeated 4986 times
Oct 28 16:06:25 ns-test ods-auditor[7646]: Auditor starting on gbg.sunet.se
Oct 28 16:06:25 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:25 ns-test last message repeated 15 times
Oct 28 16:06:25 ns-test ods-auditor[7646]: Auditing gbg.sunet.se zone : NSEC3 SIGNED
Oct 28 16:06:25 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:26 ns-test last message repeated 2376 times
Oct 28 16:06:26 ns-test ods-auditor[7651]: Auditor starting on 2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa
Oct 28 16:06:26 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:26 ns-test last message repeated 78 times
Oct 28 16:06:26 ns-test ods-auditor[7646]: SOA differs : from 2011051814 to 2011102801
Oct 28 16:06:26 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:26 ns-test last message repeated 993 times
Oct 28 16:06:26 ns-test ods-auditor[7651]: Auditing 2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa zone : NSEC3 SIGNED
Oct 28 16:06:26 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:26 ns-test last message repeated 2935 times
Oct 28 16:06:26 ns-test ods-auditor[7646]: Finished auditing gbg.sunet.se zone
Oct 28 16:06:26 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:26 ns-test last message repeated 7910 times
Oct 28 16:06:26 ns-test ods-auditor[7642]: Auditor starting on chalmers.eu
Oct 28 16:06:26 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:26 ns-test last message repeated 13 times
Oct 28 16:06:26 ns-test ods-auditor[7642]: Auditing chalmers.eu zone : NSEC3 SIGNED
Oct 28 16:06:26 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:27 ns-test last message repeated 22362 times
Oct 28 16:06:27 ns-test ods-auditor[7642]: SOA differs : from 2011063005 to 2011102801
Oct 28 16:06:27 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:27 ns-test last message repeated 1371 times
Oct 28 16:06:27 ns-test ods-auditor[7642]: Finished auditing chalmers.eu zone
Oct 28 16:06:27 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:28 ns-test last message repeated 222 times
Oct 28 16:06:28 ns-test my-reload[7676]: Start processing chalmers.eu
Oct 28 16:06:28 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:29 ns-test last message repeated 9290 times
Oct 28 16:06:29 ns-test ods-auditor[7644]: SOA differs : from 2011071301 to 2011102803
Oct 28 16:06:29 ns-test ods-signerd: [fifo] max cap reached, but drudgers seem to be on hold, notify drudgers again
Oct 28 16:06:29 ns-test last message repeated 133 times
Oct 28 16:06:30 ns-test ods-auditor[7644]: Finished auditing 120.36.192.in-addr.arpa zone
Oct 28 16:06:30 ns-test my-reload[7692]: Start processing gbg.sunet.se
Oct 28 16:06:30 ns-test ods-auditor[7701]: Auditor started
Oct 28 16:06:30 ns-test my-reload[7676]: End processing chalmers.eu
Oct 28 16:06:30 ns-test ods-signerd: [STATS] chalmers.eu RR[count=10 time=0(sec)] NSEC3[count=0 time=0(sec)] RRSIG[new=1 reused=8 time=0(sec) avg=0(sig/sec)] AUDIT[time=8(sec)] TOTAL[time=11(sec)] 
Oct 28 16:06:30 ns-test my-reload[7709]: Start processing 120.36.192.in-addr.arpa
Oct 28 16:06:31 ns-test ods-auditor[7701]: Auditor starting on itsnat.se
Oct 28 16:06:31 ns-test ods-auditor[7701]: Auditing itsnat.se zone : NSEC3 SIGNED
Oct 28 16:06:31 ns-test ods-auditor[7745]: Auditor started
Oct 28 16:06:31 ns-test ods-auditor[7745]: Auditor starting on 50.5.192.in-addr.arpa
Oct 28 16:06:31 ns-test ods-auditor[7745]: Auditing 50.5.192.in-addr.arpa zone : NSEC3 SIGNED
Oct 28 16:06:34 ns-test my-reload[7692]: End processing gbg.sunet.se
Oct 28 16:06:34 ns-test ods-signerd: [STATS] gbg.sunet.se RR[count=14 time=0(sec)] NSEC3[count=0 time=0(sec)] RRSIG[new=1 reused=12 time=0(sec) avg=0(sig/sec)] AUDIT[time=8(sec)] TOTAL[time=15(sec)] 
Oct 28 16:06:34 ns-test my-reload[7709]: End processing 120.36.192.in-addr.arpa
Oct 28 16:06:34 ns-test ods-signerd: [STATS] 120.36.192.in-addr.arpa RR[count=15 time=0(sec)] NSEC3[count=0 time=0(sec)] RRSIG[new=1 reused=22 time=0(sec) avg=0(sig/sec)] AUDIT[time=11(sec)] TOTAL[time=15(sec)] 
Oct 28 16:06:34 ns-test ods-auditor[7757]: Auditor started
Oct 28 16:06:34 ns-test ods-auditor[7755]: Auditor started
Oct 28 16:06:34 ns-test ods-auditor[7755]: Auditor starting on 16.129.in-addr.arpa
Oct 28 16:06:34 ns-test ods-auditor[7755]: Auditing 16.129.in-addr.arpa zone : NSEC3 SIGNED
Oct 28 16:06:35 ns-test ods-auditor[7757]: Auditor starting on chalmers.se
Oct 28 16:06:35 ns-test ods-auditor[7757]: Auditing chalmers.se zone : NSEC3 SIGNED
Oct 28 16:06:36 ns-test ods-auditor[7771]: Auditor started
Oct 28 16:06:37 ns-test ods-auditor[7771]: Auditor starting on 225.36.192.in-addr.arpa
Oct 28 16:06:37 ns-test ods-auditor[7771]: Auditing 225.36.192.in-addr.arpa zone : NSEC3 SIGNED
Oct 28 16:08:33 ns-test ods-auditor[7771]: SOA differs : from 2011051814 to 2011102816
Oct 28 16:08:34 ns-test ods-auditor[7771]: Finished auditing 225.36.192.in-addr.arpa zone
Oct 28 16:08:35 ns-test my-reload[7794]: Start processing 225.36.192.in-addr.arpa
Oct 28 16:08:39 ns-test my-reload[7794]: End processing 225.36.192.in-addr.arpa
Oct 28 16:08:39 ns-test ods-signerd: [STATS] 225.36.192.in-addr.arpa RR[count=260 time=1(sec)] NSEC3[count=0 time=0(sec)] RRSIG[new=1 reused=516 time=0(sec) avg=0(sig/sec)] AUDIT[time=120(sec)] TOTAL[time=125(sec)] 
Oct 28 16:08:42 ns-test ods-auditor[7640]: SOA differs : from 2011051814 to 2011102816
Oct 28 16:08:42 ns-test ods-auditor[7640]: Finished auditing 224.36.192.in-addr.arpa zone
Oct 28 16:08:42 ns-test my-reload[7821]: Start processing 224.36.192.in-addr.arpa
Oct 28 16:08:43 ns-test my-reload[7821]: End processing 224.36.192.in-addr.arpa
Oct 28 16:08:43 ns-test ods-auditor[7745]: SOA differs : from 2011070712 to 2011102816
Oct 28 16:08:43 ns-test ods-signerd: [STATS] 224.36.192.in-addr.arpa RR[count=259 time=0(sec)] NSEC3[count=0 time=0(sec)] RRSIG[new=6 reused=506 time=0(sec) avg=0(sig/sec)] AUDIT[time=143(sec)] TOTAL[time=144(sec)] 
Oct 28 16:08:44 ns-test ods-auditor[7745]: Finished auditing 50.5.192.in-addr.arpa zone
Oct 28 16:08:45 ns-test my-reload[7848]: Start processing 50.5.192.in-addr.arpa
Oct 28 16:08:47 ns-test my-reload[7848]: End processing 50.5.192.in-addr.arpa
Oct 28 16:08:47 ns-test ods-signerd: [STATS] 50.5.192.in-addr.arpa RR[count=261 time=0(sec)] NSEC3[count=0 time=0(sec)] RRSIG[new=1 reused=517 time=0(sec) avg=0(sig/sec)] AUDIT[time=134(sec)] TOTAL[time=137(sec)] 
Oct 28 16:09:48 ns-test ods-auditor[7651]: SOA differs : from 2011101801 to 2011102815
Oct 28 16:09:48 ns-test ods-auditor[7651]: Finished auditing 2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa zone
Oct 28 16:09:49 ns-test my-reload[7879]: Start processing 2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa
Oct 28 16:09:50 ns-test my-reload[7879]: End processing 2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa
Oct 28 16:09:50 ns-test ods-signerd: [STATS] 2.0.0.0.0.b.6.0.1.0.0.2.ip6.arpa RR[count=152 time=1(sec)] NSEC3[count=0 time=0(sec)] RRSIG[new=5 reused=1428 time=0(sec) avg=0(sig/sec)] AUDIT[time=208(sec)] TOTAL[time=211(sec)] 
Oct 28 16:10:06 ns-test ods-auditor[7757]: SOA differs : from 2011102805 to 2011102817
Oct 28 16:10:09 ns-test ods-auditor[7757]: Finished auditing chalmers.se zone
Oct 28 16:10:16 ns-test my-reload[7955]: Start processing chalmers.se
Oct 28 16:10:17 ns-test my-reload[7955]: End processing chalmers.se
Oct 28 16:10:17 ns-test ods-signerd: [STATS] chalmers.se RR[count=37083 time=2(sec)] NSEC3[count=0 time=0(sec)] RRSIG[new=300 reused=72056 time=6(sec) avg=50(sig/sec)] AUDIT[time=215(sec)] TOTAL[time=237(sec)] 
Oct 28 16:10:28 ns-test ods-auditor[7701]: SOA differs : from 2011102805 to 2011102819
Oct 28 16:10:29 ns-test ods-auditor[7701]: Finished auditing itsnat.se zone
Oct 28 16:10:35 ns-test my-reload[7982]: Start processing itsnat.se
Oct 28 16:10:36 ns-test my-reload[7982]: End processing itsnat.se
Oct 28 16:10:36 ns-test ods-signerd: [STATS] itsnat.se RR[count=37055 time=2(sec)] NSEC3[count=0 time=0(sec)] RRSIG[new=354 reused=71988 time=3(sec) avg=118(sig/sec)] AUDIT[time=240(sec)] TOTAL[time=257(sec)] 
Oct 28 16:11:16 ns-test ods-auditor[7755]: SOA differs : from 2011102805 to 2011102817
Oct 28 16:11:18 ns-test ods-auditor[7755]: Finished auditing 16.129.in-addr.arpa zone
Oct 28 16:11:23 ns-test my-reload[8015]: Start processing 16.129.in-addr.arpa
Oct 28 16:11:24 ns-test my-reload[8015]: End processing 16.129.in-addr.arpa
Oct 28 16:11:24 ns-test ods-signerd: [STATS] 16.129.in-addr.arpa RR[count=32960 time=6(sec)] NSEC3[count=0 time=1(sec)] RRSIG[new=237 reused=65922 time=2(sec) avg=118(sig/sec)] AUDIT[time=284(sec)] TOTAL[time=304(sec)]