[Opendnssec-user] CRITICAL: failed to sign zone example.com: General error

Havard Eidnes he at uninett.no
Sat Jan 21 11:39:32 UTC 2017


> This is opendnssec 1.4.12 and FreeBSD 11-STABLE.
>
> Today I found the following error message in my logs:
>
> | ods-signerd: [worker[4]] CRITICAL: failed to sign zone example.com:
> | General error
>
> After removing all files in /usr/local/var/opendnssec/signconf and
> /usr/local/var/opendnssec/tmp, and restartion opendnssec afterwards,
> I'll end up with:
>
> | ods-enforcerd: Zone example.com found.
> | ods-enforcerd: Policy for example.com set to default.
> | ods-enforcerd: Config will be output to /usr/local/var/opendnssec/signconf/example.com.xml.
> | ods-enforcerd: Not enough keys to satisfy zsk policy for zone:
> | example.com. keys_to_allocate(1) = keys_needed(1) - (keys_available(1) - keys_pending_retirement(1))
> | ods-enforcerd: Tried to allocate 1 keys, failed on allocating key number 1
> | ods-enforcerd: ods-enforcerd will create some more keys on its next run
> | ods-enforcerd: Error allocating zsks to zone example.com

I think I've seen a similar problem sometime before.  When I was
debugging that problem I added the patch below, which will give
you some more information (but not fix the problem).

If I recall correctly, the problem turned out to be that there
was a key stuck in a "funny state".  Ah, yes, found my message
from January 25 last year which started me on this, message-id
is <20160125.153502.606424278663993120.he at uninett.no>.

This is also related to

  https://issues.opendnssec.org/browse/OPENDNSSEC-752

In the middle there I also found that the SoftHSM database had
somehow become owned by root, and since I run OpenDNSSEC as user
"ods" that can't work properly, so that was mended, but
OpenDNSSEC could not fully recover by itself.

In my case, one problematic zone had a key stuck in "generate"
state (only visible with "--all" given to ods-ksmutil, as in
"ods-ksmutil key list -v --all --zone <zone>"), and I deleted it
with

  ods-ksmutil key delete --cka_id 15e81adbc4a30ced30cf1bab8cb2b212

At least that worked for one of the two zones I had -- the other
one had a different state.

What I think finally solved this for me was that "ods-ksmutil key
list --verbose --all" found two keys marked "NOT ALLOCATED" and
apparently with no "key tag".  Stopping OpenDNSSEC, removing
those two keys with

  ods-ksmutil key delete --cka_id 3b929d0ab308b4e1e8bf81abf1e6dafe
  ods-ksmutil key delete --cka_id b3c5b3d619c086f41f3f2ed440419f23

and restarting OpenDNSSEC made it work better again.

Regards,

- Håvard
-------------- next part --------------
$NetBSD$

Provide more debug of the output from KsmKeyPredict() et al.

--- enforcer/enforcerd/enforcer.c.orig	2016-01-21 14:31:54.000000000 +0000
+++ enforcer/enforcerd/enforcer.c
@@ -410,16 +410,21 @@ int do_keygen(DAEMONCONFIG *config, KSM_
         log_msg(NULL, LOG_ERR, "Could not predict ksk requirement for next interval for %s", policy->name);
         /* TODO exit? continue with next policy? */
     }
+    log_msg(NULL, LOG_INFO, "Predict we need %d KSKs", ksks_needed);
+
     /* Find out how many suitable keys we have */
     status = KsmKeyCountStillGood(policy->id, policy->ksk->sm, policy->ksk->bits, policy->ksk->algorithm, config->interval, rightnow, &keys_in_queue, KSM_TYPE_KSK);
     if (status != 0) {
         log_msg(NULL, LOG_ERR, "Could not count current ksk numbers for policy %s", policy->name);
         /* TODO exit? continue with next policy? */
     }
+    log_msg(NULL, LOG_INFO, "Have %d KSK keys in queue", keys_in_queue);
     /* Don't have to adjust the queue for shared keys as the prediction has already taken care of that.*/
 
     new_keys = ksks_needed - keys_in_queue;
 
+    log_msg(NULL, LOG_INFO, "Need %d new KSK keys", new_keys);
+
     /* Check capacity of HSM will not be exceeded */
     if (policy->ksk->sm_capacity != 0 && new_keys >= 0) {
         current_count = hsm_count_keys_repository(ctx, policy->ksk->sm_name);
@@ -487,12 +492,16 @@ int do_keygen(DAEMONCONFIG *config, KSM_
 
     /* Find out how many zsk keys are needed for the POLICY */
     status = KsmKeyPredict(policy->id, KSM_TYPE_ZSK, policy->shared_keys, config->interval, &zsks_needed, 0, zone_count);
+    log_msg(NULL, LOG_INFO, "Predict we need %d new ZSK keys", zsks_needed);
+
     if (status != 0) {
         log_msg(NULL, LOG_ERR, "Could not predict zsk requirement for next intervalfor %s", policy->name);
         /* TODO exit? continue with next policy? */
     }
     /* Find out how many suitable keys we have */
     status = KsmKeyCountStillGood(policy->id, policy->zsk->sm, policy->zsk->bits, policy->zsk->algorithm, config->interval, rightnow, &keys_in_queue, KSM_TYPE_ZSK);
+    log_msg(NULL, LOG_INFO, "Have %d ZSK keys in queue", keys_in_queue);
+
     if (status != 0) {
         log_msg(NULL, LOG_ERR, "Could not count current zsk numbers for policy %s", policy->name);
         /* TODO exit? continue with next policy? */
@@ -505,6 +514,8 @@ int do_keygen(DAEMONCONFIG *config, KSM_
 
     new_keys = zsks_needed - keys_in_queue;
 
+    log_msg(NULL, LOG_INFO, "Need %d new ZSK keys", new_keys);
+
     /* Check capacity of HSM will not be exceeded */
     if (policy->zsk->sm_capacity != 0 && new_keys >= 0) {
         current_count = hsm_count_keys_repository(ctx, policy->zsk->sm_name);
@@ -1324,7 +1335,9 @@ int allocateKeysToZone(KSM_POLICY *polic
             if (status == -1 || key_pair_id == 0) {
                 if (man_key_gen == 0) {
                     log_msg(NULL, LOG_WARNING, "Not enough keys to satisfy ksk policy for zone: %s. keys_to_allocate(%d) = keys_needed(%d) - (keys_available(%d) - keys_pending_retirement(%d))\n", zone_name, new_keys, keys_needed, keys_in_queue, keys_pending_retirement);
-					log_msg(NULL, LOG_WARNING, "Tried to allocate %d keys, failed on allocating key number %d", new_keys, i+1);
+		    log_msg(NULL, LOG_WARNING, "Tried to allocate %d keys, failed on allocating key number %d", new_keys, i+1);
+		    log_msg(NULL, LOG_WARNING, "Status=%d key_pair_id=%d",
+			status, key_pair_id);
                     log_msg(NULL, LOG_WARNING, "ods-enforcerd will create some more keys on its next run");
                 }
                 else {
@@ -1343,7 +1356,9 @@ int allocateKeysToZone(KSM_POLICY *polic
             if (status == -1 || key_pair_id == 0) {
                 if (man_key_gen == 0) {
                     log_msg(NULL, LOG_WARNING, "Not enough keys to satisfy zsk policy for zone: %s. keys_to_allocate(%d) = keys_needed(%d) - (keys_available(%d) - keys_pending_retirement(%d))\n", zone_name, new_keys, keys_needed, keys_in_queue, keys_pending_retirement);
-					log_msg(NULL, LOG_WARNING, "Tried to allocate %d keys, failed on allocating key number %d", new_keys, i+1);
+		    log_msg(NULL, LOG_WARNING, "Tried to allocate %d keys, failed on allocating key number %d", new_keys, i+1);
+		    log_msg(NULL, LOG_WARNING, "Status=%d key_pair_id=%d",
+			status, key_pair_id);
                     log_msg(NULL, LOG_WARNING, "ods-enforcerd will create some more keys on its next run");
                 }
                 else {


More information about the Opendnssec-user mailing list