[Opendnssec-user] ZSK expired

Matthijs Mekking matthijs at NLnetLabs.nl
Fri Jan 7 14:31:04 UTC 2011


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

Hi Casper,

On 01/07/2011 02:00 PM, Casper Gielen wrote:
> Hello,
> I've got a bit of a problem with ZSKs that are not properly rotated.
> As I understand it OpenDNSSEC should automatically create and use
> new keys. This does not seem to happen for 5 of my zones (out of a total
> of 250).
> I've tried to extract the relevant bits about one of those zones from
> the logs.
> These logs are included at the end of this mail.
> 
> General information:
> - openddnssec version 1.1.3
> - Debian version 5.0.7
> - I do not use the zone fetcher but read the zones from disk. Everytime
>   a zone changes ods-ksmutil update is used to notify opendnssec.
> - This is an internal test, not an internet-facing production system.
> - The zone is not really named example.net.
> - All zones share the same policy.
> - Keys are _not_ shared.
> - I left for vacation on Dec 24. Nobody touched the machine after that.
> 
> The first thing that grabs my attention (in the Dec 21 logs) is that the
> zone
> gets scheduled for signing twice. Is this normal?

No, a zone should always be scheduled at most once in the queue.
However, I notice the logs do mention twice that a zone is scheduled
when the zone is added.

If it is not scheduled though, it may be that a worker is working on the
zone. We set a flag, so that we know it may not be scheduled (for
example, as a result of ods-signer update).

How did you notice it was scheduled twice? Did you see it by issuing
ods-signer queue? Or did you see it in the logs? If so, do you still
have that logs, so I can investigate (offline, if you prefer)?


> In the Dec 26 logs the new bit is the line that says:
> "Scheduling task to sign zone lisspanel.net, zone in progress,
> scheduling as soon as possible"
> On Dec 28 the ZSK has expired
> On Dec 29 the DNSKEY expires
> On Dec 30 the entire RRSet fails
> According to ods-ksmutil the ZSK has been rotated.

This is what should happen if a zone is being worked on. The zone is
informed to be scheduled immediately, so that once the worker is
finished with the zone, it is put in front of the scheduler.

> 'ps' reveals a signer process that has been running for over a week on
> one of the problematic domains.

Looks like a signer process is hanging. That, of course, should also not
happen.

> I think I can fix the problem so I'm more interested in what went wrong and
> how to prevent it than a ready-made solution. Any ideas?

The only times I had similar issues is when I (accidentally) started two
signer daemons. The client (ods-signer start) checks if there is already
a daemon running, however, ods-signerd will kick of without such a check.

If that is not the case, it sounds like the signer engine is suffering
from a race condition.

> Dec 21 12:03:39 metagross ods-signerd: Zone example.net locked
> Dec 21 12:03:39 metagross ods-signerd: Scheduling task to sign zone
> example.net at 1292929419.6 with resign time 7200
> Dec 21 12:03:39 metagross ods-signerd: acquire cond
> Dec 21 12:03:39 metagross ods-signerd: notify
> Dec 21 12:03:39 metagross ods-signerd: release cond
> Dec 21 12:03:39 metagross ods-signerd: Releasing lock on zone example.net
> Dec 21 12:03:39 metagross ods-signerd: scheduling resign of zone
> 'example.net' in 4477 seconds
> Dec 21 12:03:39 metagross ods-signerd: Scheduling task to sign zone
> example.net at 1292933896.82 with resign time 7200
> Dec 21 12:03:39 metagross ods-signerd: acquire cond
> Dec 21 12:03:39 metagross ods-signerd: notify
> Dec 21 12:03:39 metagross ods-signerd: release cond
> Dec 21 12:03:39 metagross ods-signerd: Zone example.net added

It looks like the zone is just being added, given the line:

> Dec 21 12:03:39 metagross ods-signerd: Zone example.net added

Hence, probably the two log references of the zone being scheduled.
This can happen:
- - on startup
- - when receiving update [--all]
- - when receiving update <zone>, but <zone> was not found

However, this line tells me that there was a signed example.net already:

> Dec 21 12:03:39 metagross ods-signerd: scheduling resign of zone
> 'example.net' in 4477 seconds

Did some event occur at this time? Could you reason which of the three
cases happened (so that we can narrow down the search scope)?

> Dec 26 13:53:58 metagross ods-enforcerd: Zone example.net found.
> Dec 26 13:53:58 metagross ods-enforcerd: Policy for example.net set to
> default.
> Dec 26 13:53:58 metagross ods-enforcerd: Config will be output to
> /var/lib/opendnssec/signconf/example.net.xml.
> Dec 26 13:53:58 metagross ods-enforcerd: WARNING: Making non-backed up
> ZSK active, PLEASE make sure that you know the potential problems of
> using keys which are not recoverable
> Dec 26 13:53:58 metagross ods-enforcerd: INFO: ZSK has been rolled for
> example.net Dec 26 13:53:58 metagross ods-signerd: Received command:
> 'update example.net'
> Dec 26 13:53:58 metagross ods-signerd: Zone example.net locked
> Dec 26 13:53:58 metagross ods-signerd: Scheduling task to sign zone
> example.net, zone in progress, scheduling as soon as possible
> Dec 26 13:53:58 metagross ods-signerd: Releasing lock on zone example.net
> Dec 26 13:53:58 metagross ods-signerd: acquire cond
> Dec 26 13:53:58 metagross ods-signerd: notify
> Dec 26 13:53:58 metagross ods-signerd: release cond
> Dec 26 13:53:58 metagross ods-signerd: could not notify zone fetcher:
> pid file does not exist: /var/run/opendnssec/zone_fetcher.pid
> Dec 26 13:53:58 metagross ods-signerd: Releasing lock on engine
> Dec 26 13:53:58 metagross ods-signerd: Sending response: Zone config
> updated#012
> Dec 26 13:53:58 metagross ods-signerd: Done handling command
> Dec 26 13:53:58 metagross ods-signerd: Client socket shut down
> 
> Dec 28 07:00:43 metagross ods-auditor[6552]: Auditor starting on example.net
> Dec 28 07:00:43 metagross ods-auditor[6552]: SOA differs : from
> 2009012900 to 2010122414
> Dec 28 07:00:43 metagross ods-auditor[6552]: Auditing example.net zone :
> NSEC3 SIGNED
> Dec 28 07:00:43 metagross ods-auditor[6552]: Signature expiration
> (1293683046) for example.net, NS should be later than (the refresh
> period (259200) - the resign period (7200)) from now (1293516043)
> Dec 28 07:00:43 metagross ods-auditor[6552]: Signature expiration
> (1293722949) for example.net, NSEC3PARAM should be later than (the
> refresh period (259200) - the resign period (7200)) from now (1293516043)
> Dec 28 07:00:43 metagross ods-auditor[6552]: Signature expiration
> (1293711846) for 52ffgfhc643hs0eqie7g4s93317ljd9h.example.net, NSEC3
> should be later than (the refresh period (259200) - the resign period
> (7200)) from now (1293516043)
> Dec 28 07:00:43 metagross ods-auditor[6552]: Signature expiration
> (1293744549) for 7ocbpcj0npt5spm8qo90459t582e1fks.example.net, NSEC3
> should be later than (the refresh period (259200) - the resign period
> (7200)) from now (1293516043)
> Dec 28 07:00:43 metagross ods-auditor[6552]: Signature expiration
> (1293751749) for nk3p2m9k03dndvfnqha8hcdjnkb32qgs.example.net, NSEC3
> should be later than (the refresh period (259200) - the resign period
> (7200)) from now (1293516043)
> Dec 28 07:00:43 metagross ods-auditor[6552]: Signature expiration
> (1293755046) for www.example.net, A should be later than (the refresh
> period (259200) - the resign period (7200)) from now (1293516043)
> Dec 28 07:00:43 metagross ods-auditor[6552]: ZSK 53982 in use too long -
> should be max 2595600 seconds but has been 2741445 seconds
> Dec 28 07:00:43 metagross ods-auditor[6552]: Finished auditing
> example.net zone
> 
> Dec 29 06:53:53 metagross ods-auditor[14969]: Auditor starting on
> example.net
> Dec 29 06:53:53 metagross ods-auditor[14969]: SOA differs : from
> 2009012900 to 2010122414
> Dec 29 06:53:53 metagross ods-auditor[14969]: Auditing example.net zone
> : NSEC3 SIGNED
> Dec 29 06:53:53 metagross ods-auditor[14969]: Signature expiration
> (1293804042) for example.net, DNSKEY should be later than (the refresh
> period (259200) - the resign period (7200)) from now (1293602033)
> Dec 29 06:53:53 metagross ods-auditor[14969]: Signature expiration
> (1293683046) for example.net, NS should be later than (the refresh
> period (259200) - the resign period (7200)) from now (1293602033)
> Dec 29 06:53:53 metagross ods-auditor[14969]: Signature expiration
> (1293722949) for example.net, NSEC3PARAM should be later than (the
> refresh period (259200) - the resign period (7200)) from now (1293602033)
> Dec 29 06:53:53 metagross ods-auditor[14969]: Signature expiration
> (1293853234) for example.net, SOA should be later than (the refresh
> period (259200) - the resign period (7200)) from now (1293602033)
> Dec 29 06:53:53 metagross ods-auditor[14969]: Signature expiration
> (1293711846) for 52ffgfhc643hs0eqie7g4s93317ljd9h.example.net, NSEC3
> should be later than (the refresh period (259200) - the resign period
> (7200)) from now (
> Dec 29 06:53:53 metagross ods-auditor[14969]: Signature expiration
> (1293744549) for 7ocbpcj0npt5spm8qo90459t582e1fks.example.net, NSEC3
> should be later than (the refresh period (259200) - the resign period
> (7200)) from now (
> Dec 29 06:53:53 metagross ods-auditor[14969]: Signature expiration
> (1293782686) for localhost.example.net, A should be later than (the
> refresh period (259200) - the resign period (7200)) from now (1293602033)
> Dec 29 06:53:53 metagross ods-auditor[14969]: Signature expiration
> (1293751749) for nk3p2m9k03dndvfnqha8hcdjnkb32qgs.example.net, NSEC3
> should be later than (the refresh period (259200) - the resign period
> (7200)) from now (
> Dec 29 06:53:53 metagross ods-auditor[14969]: Signature expiration
> (1293755046) for www.example.net, A should be later than (the refresh
> period (259200) - the resign period (7200)) from now (1293602033)
> Dec 29 06:53:53 metagross ods-auditor[14969]: ZSK 53982 in use too long
> - should be max 2595600 seconds but has been 2827435 seconds
> Dec 29 06:53:53 metagross ods-auditor[14969]: Finished auditing
> example.net zone
> 
> Dec 30 06:37:11 metagross ods-auditor[9998]: Auditor starting on example.net
> Dec 30 06:37:11 metagross ods-auditor[9998]: SOA differs : from
> 2009012900 to 2010122414
> Dec 30 06:37:11 metagross ods-auditor[9998]: Auditing example.net zone :
> NSEC3 SIGNED
> Dec 30 06:37:11 metagross ods-auditor[9998]: Signature expiration
> (1293804042) for example.net, DNSKEY should be later than (the refresh
> period (259200) - the resign period (7200)) from now (1293687431)
> Dec 30 06:37:11 metagross ods-auditor[9998]: RRSet (example.net, NS)
> failed verification : Signature record not in validity period, tag = 53982
> Dec 30 06:37:11 metagross ods-auditor[9998]: Signature expiration
> (1293722949) for example.net, NSEC3PARAM should be later than (the
> refresh period (259200) - the resign period (7200)) from now (1293687431)
> Dec 30 06:37:11 metagross ods-auditor[9998]: Signature expiration
> (1293853234) for example.net, SOA should be later than (the refresh
> period (259200) - the resign period (7200)) from now (1293687431)
> Dec 30 06:37:11 metagross ods-auditor[9998]: Signature expiration
> (1293711846) for 52ffgfhc643hs0eqie7g4s93317ljd9h.example.net, NSEC3
> should be later than (the refresh period (259200) - the resign period
> (7200)) from now (
> 1293687431)
> Dec 30 06:37:11 metagross ods-auditor[9998]: Signature expiration
> (1293744549) for 7ocbpcj0npt5spm8qo90459t582e1fks.example.net, NSEC3
> should be later than (the refresh period (259200) - the resign period
> (7200)) from now (1293687431)
> Dec 30 06:37:11 metagross ods-auditor[9998]: Signature expiration
> (1293782686) for localhost.example.net, A should be later than (the
> refresh period (259200) - the resign period (7200)) from now (1293687431)
> Dec 30 06:37:11 metagross ods-auditor[9998]: Signature expiration
> (1293751749) for nk3p2m9k03dndvfnqha8hcdjnkb32qgs.example.net, NSEC3
> should be later than (the refresh period (259200) - the resign period
> (7200)) from now (1293687431)
> Dec 30 06:37:11 metagross ods-auditor[9998]: Signature expiration
> (1293755046) for www.example.net, A should be later than (the refresh
> period (259200) - the resign period (7200)) from now (1293687431)
> Dec 30 06:37:11 metagross ods-auditor[9998]: ZSK 53982 in use too long -
> should be max 2595600 seconds but has been 2912833 seconds
> 
> # ods-ksmutil key list -v --zone example.net SQLite database set to:
> /var/lib/opendnssec/db/kasp.db
> Keys:
> Zone:                         Keytype:      State:    Date of next
> transition:  CKA_ID:                           Repository:
>          Keytag:
> example.net                   KSK           active    2011-11-29
> 14:35:10       3c82d67b1b7b717055af9cbb3255e783  SoftHSM
>            15858
> example.net                   KSK           dsready   When required
>         3838030dc7d49c11877a1b7c2aa36d6d  SoftHSM
>     32658
> example.net                   KSK           dsready   When required
>         8da6ed4b621792eab7d60a025be59e3b  SoftHSM
>     55999
> example.net                   ZSK           active    2011-01-25
> 13:53:58       d7983d5faeeb636f944b318bcc7b1a72  SoftHSM
>            19023
> example.net                   ZSK           ready     next rollover
>         854f62703e25a10588daa9ea95309f1f  SoftHSM
>     51209
> example.net                   ZSK           ready     next rollover
>         ad263bf4b84ab2a51aa1e6d606aaace2  SoftHSM
>     21570
> example.net                   ZSK           ready     next rollover
>         c56ee4470e7b25ced6b46ebdce6e10e7  SoftHSM
>     44978
> example.net                   ZSK           ready     next rollover
>         c6a3075d2fbfb0e163fea75713127f15  SoftHSM
>     65129
> 
> 
> 
> 
> 
> 
> _______________________________________________
> Opendnssec-user mailing list
> Opendnssec-user at lists.opendnssec.org
> https://lists.opendnssec.org/mailman/listinfo/opendnssec-user
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iQEcBAEBAgAGBQJNJyOnAAoJEA8yVCPsQCW5XsUH/0YzX1ElQeWTu1yH95S4+Ag/
fKqbRRRk5arvXytUnblIaHQB+NUrUfpYkWb8nLFAjNWHwhBkysq6xY5RXY1lX/xg
yc8uLEKk23XCj2OkFfVHbfKyCwmAmccuJuNdiaeZ5yV8mW7qcfxU2fuppOwEZNB5
LR4cB2R7tUO00e0yBe0erd2I4AIA9HZ0XcU5eYNQJl1thMUQoB3ijv8Ln+EFkZak
099Jnsz614MveXAWVJrVPVAhVJ48jWtL2DugZQbx2NCyhSvjW0SwdL7FT7yNR0JH
C/9OAaGHauAUWf1dJwU5iC0HmaEjXYZElmcYEiYB2XVlXXQB+Ew+LLeDG1EM4LU=
=Dq/p
-----END PGP SIGNATURE-----



More information about the Opendnssec-user mailing list