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

Sat Oct 29 11:48:29 UTC 2011

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

I would have expected that the code would be executed: queuing RRsets is
a faster operation than fetching and signing them.

Perhaps the number of tries should be higher before the additional
broadcast is done, and perhaps it should be a verbose message instead of
a warning...

Best regards,
  Matthijs

On 10/28/2011 04:28 PM, Göran Bengtson wrote:
> 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)]
> 
> 
> 
> _______________________________________________
> Opendnssec-develop mailing list
> Opendnssec-develop at lists.opendnssec.org
> https://lists.opendnssec.org/mailman/listinfo/opendnssec-develop

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.11 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iQEcBAEBAgAGBQJOq+gMAAoJEA8yVCPsQCW51BEIAMIszTHZA4ZsTRxutw2wvtmD
/OJLS8UxOEyDkWOr79HBk1KFPK8nsl5S3IFv4ElE0/xpbmt/8SlN46TjBHVRIbqE
b6gLB+osPzhA4HePWuSuHpsGPmSj444nNKVIh/OjHXVQHhRHvoeNlocLsDCrZMPo
QvgN/J3h+KzDR6F5HdOigexg9aqOoBzU4HXpftd7hlevLhH6hFm7E/2zz+PEM1Sk
9LVVDGyJhs5eDIOGwQY760l2qBfUa/Rt78iOPjUHWn6QcfX2wDsujNJQJi1gCjqM
3X2ibIG3J8b7ZPT3WSN2Ap/pbS3Egd0bZ7/dS9OyjRdyTvbVV3TpXYwhsNcDqkg=
=tEjn
-----END PGP SIGNATURE-----