Issue #1963: CRL generation enters loop when CA loses connection to netHSM. - dogtagpki

dogtagpki

#1963 CRL generation enters loop when CA loses connection to netHSM.

Closed: Fixed Opened Feb 16, 2016 by dsirrine.

Steps to Reproduce:

1. Start pki-ca subsystem configured with netHSM
2. Disconnect netHSM from network and re-connect during CRL signing

Actual results:

2760.CRLIssuingPoint-MasterCRL - [09/Dec/2015:08:00:00 UTC] [3] [3]
CRLIssuingPoint MasterCRL - Cannot update CRL. Error: Failed constructing CRL :
java.security.SignatureException: Signing operation failed: (-8152) The key
does not support the requested operation.
32760.CRLIssuingPoint-MasterCRL - [09/Dec/2015:08:00:00 UTC] [3] [3]
CASigningUnit: Operation Error - java.security.SignatureException: Signing
operation failed: (-8152) The key does not support the requested operation.
32760.CRLIssuingPoint-MasterCRL - [09/Dec/2015:08:00:00 UTC] [3] [3]
CRLIssuingPoint MasterCRL - Failed to sign or store CRL
java.security.SignatureException: Signing operation failed: (-8152) The key
does not support the requested operation.
32760.CRLIssuingPoint-MasterCRL - [09/Dec/2015:08:00:00 UTC] [3] [3]
CRLIssuingPoint MasterCRL - Cannot update CRL. Error: Failed constructing CRL :
java.security.SignatureException: Signing operation failed: (-8152) The key
does not support the requested operation.

Expected results:

Successful CRL generation

Additional info:

CA MasterCRL configuration
~~~
ca.crl.MasterCRL.allowExtensions=true
ca.crl.MasterCRL.alwaysUpdate=false
ca.crl.MasterCRL.autoUpdateInterval=1440
ca.crl.MasterCRL.caCertsOnly=false
ca.crl.MasterCRL.cacheUpdateInterval=15
ca.crl.MasterCRL.class=com.netscape.ca.CRLIssuingPoint
ca.crl.MasterCRL.dailyUpdates=*00:00,*08:00;*00:00,*08:00
ca.crl.MasterCRL.description=CA's complete Certificate Revocation List
ca.crl.MasterCRL.enable=true
ca.crl.MasterCRL.enableCRLCache=true
ca.crl.MasterCRL.enableCRLUpdates=true
ca.crl.MasterCRL.enableCacheRecovery=true
ca.crl.MasterCRL.enableCacheTesting=false
ca.crl.MasterCRL.enableDailyUpdates=true
ca.crl.MasterCRL.enableUpdateInterval=false
ca.crl.MasterCRL.extendedNextUpdate=true
ca.crl.MasterCRL.includeExpiredCerts=false
ca.crl.MasterCRL.minUpdateInterval=0
ca.crl.MasterCRL.nextUpdateGracePeriod=9660
ca.crl.MasterCRL.publishOnStart=false
ca.crl.MasterCRL.saveMemory=false
ca.crl.MasterCRL.signingAlgorithm=SHA256withRSA
ca.crl.MasterCRL.updateSchema=1
ca.crl.MasterCRL.extension.AuthorityInformationAccess.accessLocation0=
ca.crl.MasterCRL.extension.AuthorityInformationAccess.accessLocationType0=URI
ca.crl.MasterCRL.extension.AuthorityInformationAccess.accessMethod0=caIssuers
ca.crl.MasterCRL.extension.AuthorityInformationAccess.class=com.netscape.cms.cr
l.CMSAuthInfoAccessExtension
ca.crl.MasterCRL.extension.AuthorityInformationAccess.critical=false
ca.crl.MasterCRL.extension.AuthorityInformationAccess.enable=false
ca.crl.MasterCRL.extension.AuthorityInformationAccess.numberOfAccessDescription
s=1
ca.crl.MasterCRL.extension.AuthorityInformationAccess.type=CRLExtension
ca.crl.MasterCRL.extension.AuthorityKeyIdentifier.class=com.netscape.cms.crl.CM
SAuthorityKeyIdentifierExtension
ca.crl.MasterCRL.extension.AuthorityKeyIdentifier.critical=false
ca.crl.MasterCRL.extension.AuthorityKeyIdentifier.enable=false
ca.crl.MasterCRL.extension.AuthorityKeyIdentifier.type=CRLExtension
ca.crl.MasterCRL.extension.CRLNumber.class=com.netscape.cms.crl.CMSCRLNumberExt
ension
ca.crl.MasterCRL.extension.CRLNumber.critical=false
ca.crl.MasterCRL.extension.CRLNumber.enable=true
ca.crl.MasterCRL.extension.CRLNumber.type=CRLExtension
ca.crl.MasterCRL.extension.CRLReason.class=com.netscape.cms.crl.CMSCRLReasonExt
ension
ca.crl.MasterCRL.extension.CRLReason.critical=false
ca.crl.MasterCRL.extension.CRLReason.enable=true
ca.crl.MasterCRL.extension.CRLReason.type=CRLEntryExtension
ca.crl.MasterCRL.extension.DeltaCRLIndicator.class=com.netscape.cms.crl.CMSDelt
aCRLIndicatorExtension
ca.crl.MasterCRL.extension.DeltaCRLIndicator.critical=true
ca.crl.MasterCRL.extension.DeltaCRLIndicator.enable=false
ca.crl.MasterCRL.extension.DeltaCRLIndicator.type=CRLExtension
ca.crl.MasterCRL.extension.FreshestCRL.class=com.netscape.cms.crl.CMSFreshestCR
LExtension
ca.crl.MasterCRL.extension.FreshestCRL.critical=false
ca.crl.MasterCRL.extension.FreshestCRL.enable=false
ca.crl.MasterCRL.extension.FreshestCRL.numPoints=0
ca.crl.MasterCRL.extension.FreshestCRL.pointName0=
ca.crl.MasterCRL.extension.FreshestCRL.pointType0=
ca.crl.MasterCRL.extension.FreshestCRL.type=CRLExtension
ca.crl.MasterCRL.extension.InvalidityDate.class=com.netscape.cms.crl.CMSInvalid
ityDateExtension
ca.crl.MasterCRL.extension.InvalidityDate.critical=false
ca.crl.MasterCRL.extension.InvalidityDate.enable=true
ca.crl.MasterCRL.extension.InvalidityDate.type=CRLEntryExtension
ca.crl.MasterCRL.extension.IssuerAlternativeName.class=com.netscape.cms.crl.CMS
IssuerAlternativeNameExtension
ca.crl.MasterCRL.extension.IssuerAlternativeName.critical=false
ca.crl.MasterCRL.extension.IssuerAlternativeName.enable=false
ca.crl.MasterCRL.extension.IssuerAlternativeName.name0=
ca.crl.MasterCRL.extension.IssuerAlternativeName.nameType0=
ca.crl.MasterCRL.extension.IssuerAlternativeName.numNames=0
ca.crl.MasterCRL.extension.IssuerAlternativeName.type=CRLExtension
ca.crl.MasterCRL.extension.IssuingDistributionPoint.class=com.netscape.cms.crl.
CMSIssuingDistributionPointExtension
ca.crl.MasterCRL.extension.IssuingDistributionPoint.critical=true
ca.crl.MasterCRL.extension.IssuingDistributionPoint.enable=false
ca.crl.MasterCRL.extension.IssuingDistributionPoint.indirectCRL=false
ca.crl.MasterCRL.extension.IssuingDistributionPoint.onlyContainsCACerts=false
ca.crl.MasterCRL.extension.IssuingDistributionPoint.onlyContainsUserCerts=false
ca.crl.MasterCRL.extension.IssuingDistributionPoint.onlySomeReasons=
ca.crl.MasterCRL.extension.IssuingDistributionPoint.pointName=
ca.crl.MasterCRL.extension.IssuingDistributionPoint.pointType=
ca.crl.MasterCRL.extension.IssuingDistributionPoint.type=CRLExtension
~~~

--- Additional comment from Christina Fu on 2015-12-16 20:43 EST ---

A patch has been proposed which makes a low risk attempt to slow down the loop that could be caused by an exception.
New configuration parameters are:
ca.crl.MasterCRL.unexpectedExceptionWaitTime
  - the wait time in minutes; default is 30
  - normally you want it to be less than ca.crl.MasterCRL.autoUpdateInterval
    and ca.crl.MasterCRL.cacheUpdateInterval
ca.crl.MasterCRL.unexpectedExceptionLoopMax
  - the max number of tries allowed before the slow down mechanism kicks in;
    default is 10

cfu commented Mar 3, 2016

ported my earlier patch from Bugzilla 1290650

commit 3ff245abcf900ec30839d67a0120be42e7acff92
Author: Christina Fu cfu@redhat.com
Date: Mon Feb 22 14:35:38 2016 -0800

Ticket #1963 CRL generation enters loop when CA loses connection to netHSM.
This patch makes a low risk attempt to slow down the loop that could be
caused by an unexpected exception caused by the unavailability of a
dependant component (e.g. HSM, LDAP) in the middle of CRL generation/update.
New configuration parameters are:
ca.crl.MasterCRL.unexpectedExceptionWaitTime
- the wait time in minutes; default is 30
- normally you want it to be less than ca.crl.MasterCRL.autoUpdateInterval
    and ca.crl.MasterCRL.cacheUpdateInterval
ca.crl.MasterCRL.unexpectedExceptionLoopMax
- the max number of tries allowed before the slow down mechanism kicks in;
    default is 10
When such unexpected failure happens, a loop counter is kept and checked
against the unexpectedExceptionLoopMax.  If the loop counter exceeds the
unexpectedExceptionLoopMax, then the current time is checked against the
time of the failure, where the time lapse must exceed the
unexpectedExceptionWaitTime to trigger a delay.  This delay is the
counter measure to mitigate the amount of log messages that could flood
the log(s).
The delay is calcuated like this:
    waitTime = mUnexpectedExceptionWaitTime - (now - timeOfUnexpectedFailure);

cfu commented Mar 3, 2016

Test info:
This feature can be tested using either HSM or LDAP srever. I used the LDAP out of convenience.
Example config:
ca.crl.MasterCRL.autoUpdateInterval=8
ca.crl.MasterCRL.cacheUpdateInterval=5
ca.crl.MasterCRL.unexpectedExceptionLoopMax=0
ca.crl.MasterCRL.unexpectedExceptionWaitTime=5

I shutdown the internal ldap server and observe.

I observed the following debug log entries (search for "unexpectedFailure":
[01/Mar/2016:16:20:00][CRLIssuingPoint-MasterCRL]: CRLIssuingPoint:run(): unexpectedFailure occurred:Failed constructing CRL : Failed to connect LDAP server Could not connect to LDAP server host dhcp-16-218.sjc.redhat.com port 389 Error netscape.ldap.LDAPException: failed to connect to server ldap://dhcp-16-218.sjc.redhat.com:389 (91)
...
[01/Mar/2016:16:24:07][CRLIssuingPoint-MasterCRL]: CRLIssuingPoint:run(): in unexpectedFailure. mUnexpectedExceptionLoopMax reached with loopCounter =1, loop slowdown procedure ensues
[01/Mar/2016:16:24:07][CRLIssuingPoint-MasterCRL]: CRLIssuingPoint:run(): in unexpectedFailure. now= 1456878247343; timeOfUnexpectedFailure = 1456878000016
[01/Mar/2016:16:24:07][CRLIssuingPoint-MasterCRL]: CRLIssuingPoint:run(): wait time after last failure:52673
...
[01/Mar/2016:16:25:00][CRLIssuingPoint-MasterCRL]: CRLIssuingPoint:run(): before CRL generation
...

Notice how the "unexpectedFailure occurred:" time was logged at [01/Mar/2016:16:20:00],and the "before CRL generation" time was [01/Mar/2016:16:25:00], which is exactly 5 minutes as configured with ca.crl.MasterCRL.unexpectedExceptionWaitTime=5.

here is the next loop (again, look for "unexpectedFailure:), happening 8 minutes later, due to ca.crl.MasterCRL.autoUpdateInterval=8:

[01/Mar/2016:16:28:00][CRLIssuingPoint-MasterCRL]: CRLIssuingPoint:run(): unexpectedFailure occurred:Failed constructing CRL : Failed to connect LDAP server Could not connect to LDAP server host dhcp-16-218.sjc.redhat.com port 389 Error netscape.ldap.LDAPException: failed to connect to server ldap://dhcp-16-218.sjc.redhat.com:389 (91)
...
[01/Mar/2016:16:29:07][CRLIssuingPoint-MasterCRL]: CRLIssuingPoint:run(): in unexpectedFailure. mUnexpectedExceptionLoopMax reached with loopCounter =1, loop slowdown procedure ensues
[01/Mar/2016:16:29:07][CRLIssuingPoint-MasterCRL]: CRLIssuingPoint:run(): in unexpectedFailure. now= 1456878547343; timeOfUnexpectedFailure = 1456878480012
[01/Mar/2016:16:29:07][CRLIssuingPoint-MasterCRL]: CRLIssuingPoint:run(): wait time after last failure:232669
...
[01/Mar/2016:16:33:00][CRLIssuingPoint-MasterCRL]: CRLIssuingPoint:run(): before CRL generation

In this 2nd loop, you should be able to observe the same thing.

you can also change the ca.crl.MasterCRL.unexpectedExceptionLoopMax to a higher number to allow a few more loops to occur before hitting it with the mitigation.

Metadata Update from @dsirrine:
- Issue assigned to cfu
- Issue set to the milestone: 10.3.0.a1

Feb 27, 2017

dmoluguw commented Oct 4, 2020

Dogtag PKI is moving from Pagure issues to GitHub issues. This means that existing or new
issues will be reported and tracked through Dogtag PKI's GitHub Issue tracker.

This issue has been cloned to GitHub and is available here:
https://github.com/dogtagpki/pki/issues/2324

If you want to receive further updates on the issue, please navigate to the
GitHub issue and click on Subscribe button.

Thank you for understanding, and we apologize for any inconvenience.

Metadata

Assignee

cfu

Tags

None

Blocking

None

Depending on

None

Priority

Normal

version

None

feature

None

proposedpriority

None

reviewer

None

proposedmilestone

None

type

defect

component

CRL

rhbz

https://bugzilla.redhat.com/show_bug.cgi?id=1308772

origin

RHCust

dogtagpki

#1963 CRL generation enters loop when CA loses connection to netHSM. Closed: Fixed Opened Feb 16, 2016 by dsirrine.

Metadata

#1963 CRL generation enters loop when CA loses connection to netHSM.

Closed: Fixed Opened Feb 16, 2016 by dsirrine.