1869605 – KRA Transport and Storage Certificates do not renew

Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.

Bug 1869605 - KRA Transport and Storage Certificates do not renew

Summary: KRA Transport and Storage Certificates do not renew

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Fedora
Classification:	Fedora
Component:	freeipa
Sub Component:
Version:	32
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	---
Assignee:	IPA Maintainers
QA Contact:	Fedora Extras Quality Assurance
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	1872603 1872604 1875563 1883639
TreeView+	depends on / blocked

Reported:	2020-08-18 10:50 UTC by Martin Kosek
Modified:	2021-03-29 13:18 UTC (History)
CC List:	20 users (show)
Fixed In Version:	freeipa-4.9.2-2.fc33 freeipa-4.9.2-2.fc32
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Clones:	1872603 1875563 (view as bug list)
Environment:
Last Closed:	2021-02-24 20:40:43 UTC
Type:	Bug
Embargoed:
Dependent Products:

Attachments	(Terms of Use)
Failing PKI instance journal (1.72 MB, text/plain) 2020-09-15 07:00 UTC, Martin Kosek	no flags	Details
View All

Description Martin Kosek 2020-08-18 10:50:44 UTC

Description of problem:
My long-running FreeIPA public demo instance (upgraded to the newest Fedora from 2018) cannot update KRA certificates. They always end up with error "Server at "http://ipa.demo1.freeipa.org:8080/ca/ee/ca/profileSubmit" replied: Missing credential: sessionID"

# getcert list -i 20190903113316
Number of certificates and requests being tracked: 11.
Request ID '20190903113316':
	status: CA_UNREACHABLE
	ca-error: Internal error
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='storageCert cert-pki-kra',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='storageCert cert-pki-kra',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=DEMO1.FREEIPA.ORG
	subject: CN=KRA Storage Certificate,O=DEMO1.FREEIPA.ORG
	expires: 2020-08-19 10:35:41 UTC
	key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
	eku: id-kp-clientAuth
	profile: caInternalAuthDRMstorageCert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "storageCert cert-pki-kra"
	track: yes
	auto-renew: yes

# getcert resubmit -i 20190903113316


# getcert list -i 20190903113316
Number of certificates and requests being tracked: 11.
Request ID '20190903113316':
	status: MONITORING
	ca-error: Server at "http://ipa.demo1.freeipa.org:8080/ca/ee/ca/profileSubmit" replied: Missing credential: sessionID
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='storageCert cert-pki-kra',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='storageCert cert-pki-kra',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=DEMO1.FREEIPA.ORG
	subject: CN=KRA Storage Certificate,O=DEMO1.FREEIPA.ORG
	expires: 2020-08-19 10:35:41 UTC
	key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
	eku: id-kp-clientAuth
	profile: caInternalAuthDRMstorageCert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "storageCert cert-pki-kra"
	track: yes
	auto-renew: yes


Version-Release number of selected component (if applicable):
freeipa-server-4.8.7-1.fc32.x86_64
pki-ca-10.9.0-0.4.fc32.noarch
pki-kra-10.9.0-0.4.fc32.noarch
certmonger-0.79.11-2.fc32.x86_64

How reproducible:
Always

Steps to Reproduce:
1. Check the status of renewed certificates with "getcert list"
2. Move the date or wait 1 week before KRA Transport/Storage Certificate expires
3. See if the certificate renews

Actual results:
Certificate does not renew

Expected results:
Certificate renews

Additional info:
I assume that the root cause is somewhere in updates of the certmonger tracking list.

Comment 1 Martin Kosek 2020-08-18 10:53:45 UTC

Starting with FreeIPA component first, as this problem may be specific to FreeIPA deployment or upgrade process, rather than pki-core component (feel free to change!)

Comment 2 Rob Crittenden 2020-08-18 20:58:42 UTC

I don't believe this is an issue with certmonger, it seems to be correctly reporting back an error from the CA.

Indeed this ignores IPA altogether and renews directly against the CA using the RA cert for auth.

So you need to look in the CA debug log for more details.

The journal may include the output that certmonger received.

Comment 3 Martin Kosek 2020-08-19 12:36:35 UTC

Good point. Let me include output from certmonger and related PKI error file.

# systemctl status certmonger.service -l
● certmonger.service - Certificate monitoring and PKI enrollment
     Loaded: loaded (/usr/lib/systemd/system/certmonger.service; enabled; vendor preset: disabled)
     Active: active (running) since Wed 2020-08-19 05:02:24 UTC; 7h ago
   Main PID: 807 (certmonger)
      Tasks: 2 (limit: 2335)
     Memory: 119.2M
        CPU: 25min 949ms
     CGroup: /system.slice/certmonger.service
             ├─  807 /usr/sbin/certmonger -S -p /run/certmonger.pid -n -d2
             └─11733 /usr/bin/python3 -I /usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit

Aug 19 12:35:57 ipa.demo1.freeipa.org certmonger[11733]: Kh2TvPM0a8/8kr4WqVKH6GptBArjV/tRFRn1lr7xv1UkNoE6oy/ES2xDjrlzRTtp
Aug 19 12:35:57 ipa.demo1.freeipa.org certmonger[11733]: ZUQYCdrldOYWNrrKFtG5vq2jOd2tvYdwCcy33Rrszu0gc7EAH5qDiQ==
Aug 19 12:35:57 ipa.demo1.freeipa.org certmonger[11733]: -----END CERTIFICATE-----
Aug 19 12:35:57 ipa.demo1.freeipa.org certmonger[11733]: " for child.
Aug 19 12:35:57 ipa.demo1.freeipa.org certmonger[11733]: 2020-08-19 12:35:57 [11733] Redirecting stdin to /dev/null, leaving stdout and stderr open for child "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Aug 19 12:35:57 ipa.demo1.freeipa.org certmonger[11733]: 2020-08-19 12:35:57 [11733] Running enrollment helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Aug 19 12:35:59 ipa.demo1.freeipa.org /dogtag-ipa-ca-renew-agent-submit[11733]: Forwarding request to dogtag-ipa-renew-agent
Aug 19 12:35:59 ipa.demo1.freeipa.org dogtag-ipa-renew-agent-submit[11738]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Aug 19 12:35:59 ipa.demo1.freeipa.org /dogtag-ipa-ca-renew-agent-submit[11733]: dogtag-ipa-renew-agent returned 2
Aug 19 12:35:59 ipa.demo1.freeipa.org certmonger[807]: 2020-08-19 12:35:59 [807] Certificate submission still ongoing.

Comment 4 Martin Kosek 2020-08-19 12:39:59 UTC

/var/log/pki/pki-tomcat/ca/debug.2020-07-14.log:

2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Property useThreadNaming not found
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting useThreadNaming=false
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CMSServlet:service() uri: /ca/ee/ca/profileSubmit
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CMSServlet::service() param name='profileId' value='caInternalAuthAuditSigningCert'
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CMSServlet::service() param name='cert_request_type' value='pkcs10'
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CMSServlet::service() param name='cert_request' value='(sensitive)'
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CMSServlet::service() param name='xml' value='true'
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CMSServlet::service() param name='requestor_name' value='IPA'
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CMSServlet: caProfileSubmit start to service.
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: GET r=http-request-params,k=authenticator,v=null,d=null
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: xmlOutput true
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: ProfileSubmitServlet: isRenewal false
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Property processor.caProfileSubmit.profileId not found
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.profileId=
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.authzResourceName=certServer.ee.profile
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.authzResourceName=certServer.ee.profile
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.authzResourceName=certServer.ee.profile
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Property processor.caProfileSubmit.authMgr not found
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.authMgr=
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.getClientCert=false
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.getClientCert=false
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.getClientCert=false
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Property processor.caProfileSubmit.profileSubId not found
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.profileSubId=
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Property processor.caProfileSubmit.ACLinfo not found
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.ACLinfo=
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.authzMgr=BasicAclAuthz
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.authzMgr=BasicAclAuthz
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting processor.caProfileSubmit.authzMgr=BasicAclAuthz
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting authz.sourceType=ldap
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting authz.sourceType=ldap
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: ServletUtils: according to ccMode, authorization for servlet: caProfileSubmit is LDAP based, not XML {1}, use default authz mgr: {2}.
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: ProfileSubmitServlet: profile: caInternalAuthAuditSigningCert
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: GET r=http-request-params,k=cert_request_type,v=pkcs10,d=null
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: GET r=http-request-params,k=cert_request,v=-----BEGIN NEW CERTIFICATE REQUEST-----
MIIDZTCCAk0CAQAwMDEaMBgGA1UECgwRREVNTzEuRlJFRUlQQS5PUkcxEjAQBgNV
BAMMCUtSQSBBdWRpdDCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAM6E
Y4UA9vLK3jR4cekjbfYNYr8CFAliA/QxgPWRnqh6VfvZ3+Y3378csIuhEFefR89R
93oPt5OCqotEBHKCHkDqYKHeqvS+NKE5DicfEeOjRuR2sWYFXTVNn+1W6nNK0Y/l
PIYg/DeQ4UU08nlzNnYxFIu16bZ/UQcta00a2Wb119RdSQbTzptLJSRZt/WattNs
KzOzi0p18gDKPqRVVbV3VR77Yq6KnsIweTB9N7gaWNfPpU5YWBf4QTVEK43HBNF4
6s3X8zdYXh+Zn+FmLCSDEELaLbBCZVZ+lM7oYE7WxfvD3hmTSZYIOhOk37Rr+x1p
WwBS8BuK1a03cOITLDECAwEAAaCB7zBJBgkqhkiG9w0BCRQxPB46AGEAdQBkAGkA
dABTAGkAZwBuAGkAbgBnAEMAZQByAHQAIABjAGUAcgB0AC0AcABrAGkALQBrAHIA
YTCBoQYJKoZIhvcNAQkOMYGTMIGQMA4GA1UdDwEBAAQEAwIGwDAMBgNVHRMBAf8E
AjAAMCAGA1UdDgEBAAQWBBTBT9Znj0Ri1GOS4Vnb0ahgUDNeEzBOBgkrBgEEAYI3
FAIBAQAEPh48AGMAYQBJAG4AdABlAHIAbgBhAGwAQQB1AHQAaABBAHUAZABpAHQA
UwBpAGcAbgBpAG4AZwBDAGUAcgB0MA0GCSqGSIb3DQEBCwUAA4IBAQBgrQdFWBwl
V8lleevn+FYehajPZBvz4/Q+k+wW4pdy7r+GisQEJsW/9o9U4O9YUY/5AAnfraGw
Xx/sQImFO+DFXAFw2ePnIvgR8Gno5Cdj9PcmRHiMqO7vwcKuN2Q8iRqa32DgoalH
wFhkkDE/5V6u5nlD4E33HLuaCTnvTvAMJYM5GLshEyBxOwhRZAkZDzYz/cUR/sWi
7wyjxo4TWDRsKPX6QEl1q8RG+VUIzYdTry4MLjGxioF1FG4kO5UTRfuejJjzAnrr
ghW5Z3bAWupjjFrukTg14PIKuMPLy08T4gaWZHOuxuBztbPw1B0bcYaq9Wy5udTz
eqf3blQPb9KL
-----END NEW CERTIFICATE REQUEST-----
,d=null
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: GET r=http-request-params,k=requestor_name,v=IPA,d=null
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: GET r=http-request-params,k=requestor_email,v=null,d=null
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: GET r=http-request-params,k=requestor_phone,v=null,d=null
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CAProcessor: Input Parameters:
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CAProcessor: - isRenewal: false
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CAProcessor: - remoteHost: 127.0.0.1
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CAProcessor: - cert_request_type: pkcs10
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CAProcessor: - profileId: caInternalAuthAuditSigningCert
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CAProcessor: - cert_request: (sensitive)
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CAProcessor: - requestor_name: IPA
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CAProcessor: - remoteAddr: 127.0.0.1
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: EnrollmentProcessor: isRenewal false
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: EnrollmentProcessor: profileId caInternalAuthAuditSigningCert
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting enable=true
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting enable=true
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: EnrollmentProcessor: set Inputs into profile Context
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: EnrollmentProcessor: authenticator TokenAuth found
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CertProcessor: Authentication credentials:
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: EnrollmentProcessor: set sslClientCertProvider
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: authenticate: authentication required.
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CAProcessor: in auditSubjectID
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CAProcessor: auditSubjectID auditContext {sslClientCertProvider=com.netscape.cms.servlet.profile.SSLClientCertProvider@c1c7291, profileContext={cert_request_type=pkcs10, cert_request=-----BEGIN NEW CERTIFICATE REQUEST-----
MIIDZTCCAk0CAQAwMDEaMBgGA1UECgwRREVNTzEuRlJFRUlQQS5PUkcxEjAQBgNV
BAMMCUtSQSBBdWRpdDCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAM6E
Y4UA9vLK3jR4cekjbfYNYr8CFAliA/QxgPWRnqh6VfvZ3+Y3378csIuhEFefR89R
93oPt5OCqotEBHKCHkDqYKHeqvS+NKE5DicfEeOjRuR2sWYFXTVNn+1W6nNK0Y/l
PIYg/DeQ4UU08nlzNnYxFIu16bZ/UQcta00a2Wb119RdSQbTzptLJSRZt/WattNs
KzOzi0p18gDKPqRVVbV3VR77Yq6KnsIweTB9N7gaWNfPpU5YWBf4QTVEK43HBNF4
6s3X8zdYXh+Zn+FmLCSDEELaLbBCZVZ+lM7oYE7WxfvD3hmTSZYIOhOk37Rr+x1p
WwBS8BuK1a03cOITLDECAwEAAaCB7zBJBgkqhkiG9w0BCRQxPB46AGEAdQBkAGkA
dABTAGkAZwBuAGkAbgBnAEMAZQByAHQAIABjAGUAcgB0AC0AcABrAGkALQBrAHIA
YTCBoQYJKoZIhvcNAQkOMYGTMIGQMA4GA1UdDwEBAAQEAwIGwDAMBgNVHRMBAf8E
AjAAMCAGA1UdDgEBAAQWBBTBT9Znj0Ri1GOS4Vnb0ahgUDNeEzBOBgkrBgEEAYI3
FAIBAQAEPh48AGMAYQBJAG4AdABlAHIAbgBhAGwAQQB1AHQAaABBAHUAZABpAHQA
UwBpAGcAbgBpAG4AZwBDAGUAcgB0MA0GCSqGSIb3DQEBCwUAA4IBAQBgrQdFWBwl
V8lleevn+FYehajPZBvz4/Q+k+wW4pdy7r+GisQEJsW/9o9U4O9YUY/5AAnfraGw
Xx/sQImFO+DFXAFw2ePnIvgR8Gno5Cdj9PcmRHiMqO7vwcKuN2Q8iRqa32DgoalH
wFhkkDE/5V6u5nlD4E33HLuaCTnvTvAMJYM5GLshEyBxOwhRZAkZDzYz/cUR/sWi
7wyjxo4TWDRsKPX6QEl1q8RG+VUIzYdTry4MLjGxioF1FG4kO5UTRfuejJjzAnrr
ghW5Z3bAWupjjFrukTg14PIKuMPLy08T4gaWZHOuxuBztbPw1B0bcYaq9Wy5udTz
eqf3blQPb9KL
-----END NEW CERTIFICATE REQUEST-----
, requestor_name=IPA}}
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CAProcessor auditSubjectID: subjectID: null
2020-08-19 12:35:50 [http-nio-8080-exec-23] SEVERE: CAProcessor: authentication error: Missing credential: sessionID
Missing credential: sessionID
	at com.netscape.cms.servlet.common.AuthCredentials.set(AuthCredentials.java:57)
	at com.netscape.cms.servlet.processors.CAProcessor.authenticate(CAProcessor.java:423)
	at com.netscape.cms.servlet.processors.CAProcessor.authenticate(CAProcessor.java:482)
	at com.netscape.cms.servlet.cert.EnrollmentProcessor.processEnrollment(EnrollmentProcessor.java:178)
	at com.netscape.cms.servlet.cert.EnrollmentProcessor.processEnrollment(EnrollmentProcessor.java:97)
	at com.netscape.cms.servlet.profile.ProfileSubmitServlet.processEnrollment(ProfileSubmitServlet.java:276)
	at com.netscape.cms.servlet.profile.ProfileSubmitServlet.process(ProfileSubmitServlet.java:130)
	at com.netscape.cms.servlet.base.CMSServlet.service(CMSServlet.java:494)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
	at sun.reflect.GeneratedMethodAccessor45.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:282)
	at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:279)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
	at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:314)
	at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:170)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:225)
	at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:47)
	at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:149)
	at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:145)
	at java.security.AccessController.doPrivileged(Native Method)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:144)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
	at sun.reflect.GeneratedMethodAccessor44.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:282)
	at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:279)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
	at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:314)
	at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:253)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:191)
	at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:47)
	at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:149)
	at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:145)
	at java.security.AccessController.doPrivileged(Native Method)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:144)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
	at com.netscape.cms.tomcat.ExternalAuthenticationValve.invoke(ExternalAuthenticationValve.java:82)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:373)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)

2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: SignedAuditLogger: event AUTH
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting pidDir=/var/run/pki/tomcat
2020-08-19 12:35:50 [http-nio-8080-exec-23] FINEST: Getting pidDir=/var/run/pki/tomcat
2020-08-19 12:35:50 [http-nio-8080-exec-23] SEVERE: ProfileSubmitServlet: authentication error in processing request: Missing credential: sessionID
Missing credential: sessionID
	at com.netscape.cms.servlet.common.AuthCredentials.set(AuthCredentials.java:57)
	at com.netscape.cms.servlet.processors.CAProcessor.authenticate(CAProcessor.java:423)
	at com.netscape.cms.servlet.processors.CAProcessor.authenticate(CAProcessor.java:482)
	at com.netscape.cms.servlet.cert.EnrollmentProcessor.processEnrollment(EnrollmentProcessor.java:178)
	at com.netscape.cms.servlet.cert.EnrollmentProcessor.processEnrollment(EnrollmentProcessor.java:97)
	at com.netscape.cms.servlet.profile.ProfileSubmitServlet.processEnrollment(ProfileSubmitServlet.java:276)
	at com.netscape.cms.servlet.profile.ProfileSubmitServlet.process(ProfileSubmitServlet.java:130)
	at com.netscape.cms.servlet.base.CMSServlet.service(CMSServlet.java:494)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
	at sun.reflect.GeneratedMethodAccessor45.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:282)
	at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:279)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
	at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:314)
	at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:170)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:225)
	at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:47)
	at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:149)
	at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:145)
	at java.security.AccessController.doPrivileged(Native Method)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:144)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
	at sun.reflect.GeneratedMethodAccessor44.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:282)
	at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:279)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
	at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:314)
	at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:253)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:191)
	at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:47)
	at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:149)
	at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:145)
	at java.security.AccessController.doPrivileged(Native Method)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:144)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
	at com.netscape.cms.tomcat.ExternalAuthenticationValve.invoke(ExternalAuthenticationValve.java:82)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:690)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:373)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)

2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: CMSServlet: curDate: Wed Aug 19 12:35:50 UTC 2020 id: caProfileSubmit time: 21

Comment 5 Rob Crittenden 2020-08-20 11:58:09 UTC

I have no idea what session ID this is referring to and what is responsible for setting it. Need some assistance from the pki team on this.

Comment 6 Alex Scheel 2020-08-20 15:29:49 UTC

Rob, note the profile used above:

2020-08-19 12:35:50 [http-nio-8080-exec-23] FINE: EnrollmentProcessor: profileId caInternalAuthAuditSigningCert

This profile (internalAuthAuditSigningCert) requires token authentication (passed as "sessionID"). This is only used during installation. 


However, above, in mkosek's request, we see:

	profile: caInternalAuthDRMstorageCert

So something is not correctly passing or handling the profile. It isn't obvious to me how or why or what changed, so I'll needinfo jmagne and cfu to see if they can assist.

Comment 7 Christina Fu 2020-08-24 17:50:21 UTC

As Alex pointed out, those caInternalXXX enrollment profiles require "token authentication", where tokens are per "session" during installation.  They are only meant to be used for installation, unless of course someone has changed the "auth.instance_id" in those profiles to something else.  And that I would not recommend.  It's best if you create new profiles specific to your need.

Seeing that you seem to want to do "renewal", did you really intend to use those caInternalXXX profiles?  Has it always been the case for FreeIPA to renew using those profiles?  If so, then I suspect someone must have changed the auth.instance_id values for those profiles.

If you want to use RA cert to authenticate, the auth.instance_id value in the profile should be "AgentCertAuth".
Hope this helps.

Comment 8 Alex Scheel 2020-08-24 21:37:10 UTC

To clarify, this is a bug in FreeIPA.


These profiles are for subsystem installation only. If you require similar profiles with agent auth, please ask. Until then, this commit should probably be reverted, as it will not work.

https://github.com/freeipa/freeipa/commit/3c388f5a228b767dfd92bd824dfced166acda143
https://github.com/freeipa/freeipa/blob/master/ipaserver/install/krainstance.py#L72

Comment 9 Christina Fu 2020-08-24 22:01:21 UTC

So, I think the proper KRA profiles to use would be caStorageCert.cfg and caTransportCert.cfg.  However, the out of box authentication method used is manual agent approval for those.

If you wish to use RA cert to authenticate, copy each profile to something like ipaKRAStorageCert and ipaKRATransportCert, change the authentication id to the following:
auth.instance_id=AgentCertAuth

Anyways, there's a bit more details than that to create customized profiles.  Is this what you guys need from us?

Comment 10 Alexander Bokovoy 2020-08-25 09:49:37 UTC

Yes, more details would be good to have.

My guess is that we need:

1. Create new profiles, as outlined by Christina in comment #9.

2. Add the profiles to LDAP store during upgrade or install

3. Add use of KRA profiles to a specific CA ACL so that IPA replica host can request one

4. Make sure to use the profiles when issuing KRA certificate

5. Convert existing KRA certificate's request in certmonger to use new profile

Most of these steps are on IPA side.

Comment 11 Martin Kosek 2020-08-26 07:10:00 UTC

Thanks for the quick analysis. I think you are getting somewhere.
Please let me know if you need to get an access to the FreeIPA demo machine, I can easily provide it. But I assume this is a general problem, since I was not doing lot of special configuration to the FreeIPA demo, I just keep it up-to-date.

Comment 12 Rob Crittenden 2020-08-26 19:19:10 UTC

I think Alexander's proposal is the way to go. We can't revert the suggested commit as it does more than just define the KRA tracking profiles. We'll adjust it with the new names once the profiles are created.

Comment 13 Martin Kosek 2020-09-15 06:58:35 UTC

I noticed that the current FreeIPA demo's PKI instance is misbehaving, likely thanks the expired KRA certificate. PKI cannot cope with it and stops eventually, causing further issues in the FreeIPA demo. I will attach it's journal.

Is there anything that can be done to workaround the issue? I also considered just uninstalling the KRA subsystem, but I do not think there is an uninstaller for that, yet.

Comment 14 Martin Kosek 2020-09-15 07:00:06 UTC

Created attachment 1714889 [details]
Failing PKI instance journal

Comment 15 Rob Crittenden 2020-09-15 13:33:08 UTC

The KRA uninstaller was removed from IPA in 5d3a0e6758866239c886e998a6d89c5a4b150184

There is surely some manual way we can add the new profiles. I'll see what I can work out based on the upstream pki commit.

Comment 16 Rob Crittenden 2020-09-15 15:30:13 UTC

I have the feeling that auditSigningCert cert-pki-kra needs a new profile as well.

Comment 17 Rob Crittenden 2020-10-15 12:26:02 UTC

Upstream ticket:
https://pagure.io/freeipa/issue/8545

Comment 18 Rob Crittenden 2020-10-15 12:27:15 UTC

CS is going to deliver a new profile for the audit signing certificate. The transport and storage certificates will use different, existing profiles.

The fix on the IPA side is to modify the expected profiles in krainstance.py and run ipa-server-upgrade to load the new profile into LDAP and re-generated the certmonger tracking requests.

The IPA diff is:

diff --git a/ipaserver/install/krainstance.py b/ipaserver/install/krainstance
.py
index a5f169442..2bcff3bc0 100644
--- a/ipaserver/install/krainstance.py
+++ b/ipaserver/install/krainstance.py
@@ -65,9 +65,9 @@ class KRAInstance(DogtagInstance):
     # use for that certificate.  'configure_renewal()' reads this
     # dict.  The profile MUST be specified.
     tracking_reqs = {
-        'auditSigningCert cert-pki-kra': 'caInternalAuthAuditSigningCert',
-        'transportCert cert-pki-kra': 'caInternalAuthTransportCert',
-        'storageCert cert-pki-kra': 'caInternalAuthDRMstorageCert',
+        'auditSigningCert cert-pki-kra': 'caAuditSigningCert',
+        'transportCert cert-pki-kra': 'caTransportCert',
+        'storageCert cert-pki-kra': 'caStorageCert',
     }
 
     def __init__(self, realm):

The new caAuditSigningCert profile was added in nightly build pki-ca-10.10.0-0.1.alpha1.20201014121037UTC.4f4e5a29.fc32.noarch

I've manually tested upgrades and fresh installs then forced renewal on all three certs and they were all successfully renewed.

Comment 19 Florence Blanc-Renaud 2020-12-01 11:59:25 UTC

Fixed upstream
master:
https://pagure.io/freeipa/c/b691850cc9718818893291bb813cc227a8daa3d9
https://pagure.io/freeipa/c/0037b698eda11185cb5f22ff74f4b008bc24fe40
https://pagure.io/freeipa/c/6816de0892a11c203f1a2e6f7819d533c7658fa9

Comment 20 Rob Crittenden 2020-12-01 18:07:02 UTC

Fixed upstream
ipa-4-9:
https://pagure.io/freeipa/c/a9e1c014f601a567f4aa5135d02883c498835268
https://pagure.io/freeipa/c/bd4771d75f8549fe1790540764f23d47bf3d187c
https://pagure.io/freeipa/c/3e530e93c37ee71a560714e26285cd85e71557c9

Fixed upstream
ipa-4-8:
https://pagure.io/freeipa/c/69adf813acb6c37fd5b64f5713f41dce7ddf0207
https://pagure.io/freeipa/c/c3c577aead10e592bf01bc04b6a31d0cf4d4a2be
https://pagure.io/freeipa/c/c1659014d0b9e038896ba860a0d76bb70dad7bac

Comment 21 Fedora Update System 2021-02-15 21:01:58 UTC

FEDORA-2021-9ead482997 has been submitted as an update to Fedora 32. https://bodhi.fedoraproject.org/updates/FEDORA-2021-9ead482997

Comment 22 Fedora Update System 2021-02-15 21:02:10 UTC

FEDORA-2021-a53fdfcaeb has been submitted as an update to Fedora 33. https://bodhi.fedoraproject.org/updates/FEDORA-2021-a53fdfcaeb

Comment 23 Fedora Update System 2021-02-16 01:15:12 UTC

FEDORA-2021-a53fdfcaeb has been pushed to the Fedora 33 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-a53fdfcaeb`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2021-a53fdfcaeb

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 24 Fedora Update System 2021-02-16 01:18:50 UTC

FEDORA-2021-9ead482997 has been pushed to the Fedora 32 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-9ead482997`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2021-9ead482997

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 25 Fedora Update System 2021-02-24 20:40:43 UTC

FEDORA-2021-a53fdfcaeb has been pushed to the Fedora 33 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 26 Fedora Update System 2021-02-24 20:45:05 UTC

FEDORA-2021-9ead482997 has been pushed to the Fedora 32 stable repository.
If problem still persists, please make note of it in this bug report.

Comment 27 Thomas Höll 2021-03-14 17:13:05 UTC

Is there a way to recover from this? I'm on 4.9.2-4.fc33 and still have this issue.

Also, after doing a `getcert resubmit`, the CA just hangs. The following certificates are stuck at 'SUBMITTING' state:

Request ID '20201024221228':
	status: SUBMITTING
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='auditSigningCert cert-pki-kra',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='auditSigningCert cert-pki-kra',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=KRA Audit,O=MY.IPA.REALM
	expires: 2020-10-31 16:20:29 CET
	key usage: digitalSignature,nonRepudiation
	profile: caInternalAuthAuditSigningCert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "auditSigningCert cert-pki-kra"
	track: yes
	auto-renew: yes
Request ID '20201024221229':
	status: SUBMITTING
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='transportCert cert-pki-kra',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='transportCert cert-pki-kra',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=KRA Transport Certificate,O=MY.IPA.REALM
	expires: 2020-10-31 16:20:39 CET
	key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
	eku: id-kp-clientAuth
	profile: caInternalAuthTransportCert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "transportCert cert-pki-kra"
	track: yes
	auto-renew: yes
Request ID '20201024221230':
	status: SUBMITTING
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='storageCert cert-pki-kra',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='storageCert cert-pki-kra',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=KRA Storage Certificate,O=MY.IPA.REALM
	expires: 2020-10-31 16:21:19 CET
	key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
	eku: id-kp-clientAuth
	profile: caInternalAuthDRMstorageCert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "storageCert cert-pki-kra"
	track: yes
	auto-renew: yes

Comment 28 Florence Blanc-Renaud 2021-03-15 07:24:25 UTC

The 3 KRA certificates are now past their expiration date. What is the status of the other certificates, are they still valid?
Another thing to be checked is the renewal lock that is taken when renewing certificates. What is the content of /var/run/ipa/renewal.lock?

Comment 29 Thomas Höll 2021-03-15 10:14:02 UTC

Mostly. The only certificate which also can't be renewed is the last one:

Number of certificates and requests being tracked: 12.
Request ID '20180215204322':
	status: MONITORING
	stuck: no
	key pair storage: type=FILE,location='/var/kerberos/krb5kdc/kdc.key'
	certificate: type=FILE,location='/var/kerberos/krb5kdc/kdc.crt'
	CA: SelfSign
	issuer: CN=my.ipa.server,O=MY.IPA.REALM
	subject: CN=my.ipa.server,O=MY.IPA.REALM
	expires: 2021-11-23 21:43:42 CET
	principal name: krbtgt/MY.IPA.REALM.REALM
	certificate template/profile: KDCs_PKINIT_Certs
	profile: KDCs_PKINIT_Certs
	pre-save command: 
	post-save command: /usr/libexec/ipa/certmonger/renew_kdc_cert
	track: yes
	auto-renew: yes
Request ID '20201024221228':
	status: MONITORING
	ca-error: Server at "http://my.ipa.server:8080/ca/ee/ca/profileSubmit" replied: Missing credential: sessionID
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='auditSigningCert cert-pki-kra',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='auditSigningCert cert-pki-kra',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=KRA Audit,O=MY.IPA.REALM
	expires: 2020-10-31 16:20:29 CET
	key usage: digitalSignature,nonRepudiation
	profile: caInternalAuthAuditSigningCert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "auditSigningCert cert-pki-kra"
	track: yes
	auto-renew: yes
Request ID '20201024221229':
	status: MONITORING
	ca-error: Server at "http://my.ipa.server:8080/ca/ee/ca/profileSubmit" replied: Missing credential: sessionID
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='transportCert cert-pki-kra',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='transportCert cert-pki-kra',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=KRA Transport Certificate,O=MY.IPA.REALM
	expires: 2020-10-31 16:20:39 CET
	key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
	eku: id-kp-clientAuth
	profile: caInternalAuthTransportCert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "transportCert cert-pki-kra"
	track: yes
	auto-renew: yes
Request ID '20201024221230':
	status: SUBMITTING
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='storageCert cert-pki-kra',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='storageCert cert-pki-kra',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=KRA Storage Certificate,O=MY.IPA.REALM
	expires: 2020-10-31 16:21:19 CET
	key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
	eku: id-kp-clientAuth
	profile: caInternalAuthDRMstorageCert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "storageCert cert-pki-kra"
	track: yes
	auto-renew: yes
Request ID '20210223071720':
	status: MONITORING
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='auditSigningCert cert-pki-ca',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='auditSigningCert cert-pki-ca',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=CA Audit,O=MY.IPA.REALM
	expires: 2022-08-29 21:17:21 CEST
	key usage: digitalSignature,nonRepudiation
	profile: caSignedLogCert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "auditSigningCert cert-pki-ca"
	track: yes
	auto-renew: yes
Request ID '20210223071721':
	status: MONITORING
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='ocspSigningCert cert-pki-ca',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='ocspSigningCert cert-pki-ca',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=OCSP Subsystem,O=MY.IPA.REALM
	expires: 2022-08-30 20:13:39 CEST
	eku: id-kp-OCSPSigning
	profile: caOCSPCert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "ocspSigningCert cert-pki-ca"
	track: yes
	auto-renew: yes
Request ID '20210223071722':
	status: MONITORING
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='subsystemCert cert-pki-ca',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='subsystemCert cert-pki-ca',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=CA Subsystem,O=MY.IPA.REALM
	expires: 2022-08-29 21:18:06 CEST
	key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
	eku: id-kp-clientAuth
	profile: caSubsystemCert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "subsystemCert cert-pki-ca"
	track: yes
	auto-renew: yes
Request ID '20210223071723':
	status: MONITORING
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='caSigningCert cert-pki-ca',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='caSigningCert cert-pki-ca',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=Certificate Authority,O=MY.IPA.REALM
	expires: 2038-11-25 20:23:12 CET
	key usage: digitalSignature,nonRepudiation,keyCertSign,cRLSign
	profile: caCACert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "caSigningCert cert-pki-ca"
	track: yes
	auto-renew: yes
Request ID '20210223071724':
	status: MONITORING
	stuck: no
	key pair storage: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='Server-Cert cert-pki-ca',token='NSS Certificate DB',pin set
	certificate: type=NSSDB,location='/etc/pki/pki-tomcat/alias',nickname='Server-Cert cert-pki-ca',token='NSS Certificate DB'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=my.ipa.server,O=MY.IPA.REALM
	expires: 2022-08-29 21:16:42 CEST
	key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
	eku: id-kp-serverAuth,id-kp-clientAuth
	profile: caServerCert
	pre-save command: /usr/libexec/ipa/certmonger/stop_pkicad
	post-save command: /usr/libexec/ipa/certmonger/renew_ca_cert "Server-Cert cert-pki-ca"
	track: yes
	auto-renew: yes
Request ID '20210223071725':
	status: MONITORING
	stuck: no
	key pair storage: type=FILE,location='/var/lib/ipa/ra-agent.key'
	certificate: type=FILE,location='/var/lib/ipa/ra-agent.pem'
	CA: dogtag-ipa-ca-renew-agent
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=IPA RA,O=MY.IPA.REALM
	expires: 2022-08-29 21:17:29 CEST
	key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
	eku: id-kp-clientAuth
	profile: caSubsystemCert
	pre-save command: /usr/libexec/ipa/certmonger/renew_ra_cert_pre
	post-save command: /usr/libexec/ipa/certmonger/renew_ra_cert
	track: yes
	auto-renew: yes
Request ID '20210223071726':
	status: MONITORING
	stuck: no
	key pair storage: type=NSSDB,location='/etc/dirsrv/slapd-MY-IPA-REALM',nickname='Server-Cert',token='NSS Certificate DB',pinfile='/etc/dirsrv/slapd-MY-IPA-REALM/pwdfile.txt'
	certificate: type=NSSDB,location='/etc/dirsrv/slapd-MY-IPA-REALM',nickname='Server-Cert',token='NSS Certificate DB'
	CA: IPA
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=my.ipa.server,O=MY.IPA.REALM
	expires: 2022-04-21 19:18:12 CEST
	dns: my.ipa.server
	principal name: ldap/my.ipa.server.REALM
	key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
	eku: id-kp-serverAuth,id-kp-clientAuth
	profile: caIPAserviceCert
	pre-save command: 
	post-save command: /usr/libexec/ipa/certmonger/restart_dirsrv MY-IPA-REALM
	track: yes
	auto-renew: yes
Request ID '20210223071727':
	status: NEED_KEY_GEN_PIN
	stuck: yes
	key pair storage: type=FILE,location='/var/lib/ipa/private/httpd.key',pinfile='/var/lib/ipa/passwds/my.ipa.server-443-RSA'
	certificate: type=FILE,location='/var/lib/ipa/certs/httpd.crt'
	CA: IPA
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=my.ipa.server,O=MY.IPA.REALM
	expires: 2022-03-18 13:50:30 CET
	dns: my.ipa.server
	principal name: HTTP/my.ipa.server.REALM
	key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
	eku: id-kp-serverAuth,id-kp-clientAuth
	profile: caIPAserviceCert
	pre-save command: 
	post-save command: /usr/libexec/ipa/certmonger/restart_httpd
	track: yes
	auto-renew: yes



$ cat /var/run/ipa/renewal.lock
[lock]
locked = 0

Comment 30 Florence Blanc-Renaud 2021-03-16 10:32:41 UTC

1. It seems that the http certificate was renewed (based on its expiration date), not sure why the status is in NEED_KEY_GEN_PIN. Usually it means that the pin protecting the private key is invalid.
You can check the pin with "openssl rsa -in /var/lib/ipa/private/httpd.key -noout -text -passin file:/var/lib/ipa/passwds/my.ipa.server-443-RSA". If the command succeeds, the file is containing the right pin.

2. the certificates that fail to renew are certificates shared between all the KRA instances. They are renewed on the CA renewal master, then put into LDAP, and the other instances can then download them from LDAP. We need to check which server is your CA renewal master and then check if the certs were renewed on this server:

# ipa config-show | grep "CA renewal master"
  IPA CA renewal master: server.ipa.test

On the host defined as CA renewal master:
server.ipa.test# getcert list

Please note that we have a known issue when the CA renewal master does not host the KRA server: https://bugzilla.redhat.com/show_bug.cgi?id=1830344 KRA certificates will expire if the CA renewal manager isn't running that service

Comment 31 Thomas Höll 2021-03-17 07:24:47 UTC

1) The directory containing the pin file is empty:
[root@ipa ~]# ll /var/lib/ipa/passwds/
total 0

2) This is a single server installation

The server itself is running for some time now (installation date: 2016-11-24). There have been some issues related to FreeIPA during Fedora system upgrades in the past, maybe that's related somehow?

Comment 32 Rob Crittenden 2021-03-17 13:16:34 UTC

Does /var/lib/ipa/private/httpd.key begin with -----BEGIN ENCRYPTED PRIVATE KEY----- ?

What is the value of SSLPassPhraseDialog in /etc/httpd/conf.d/ssl.conf?

If the httpd key is not encrypted did you replace it at some point with some 3rd party certificate?

Comment 33 Thomas Höll 2021-03-18 10:31:34 UTC

> Does /var/lib/ipa/private/httpd.key begin with -----BEGIN ENCRYPTED PRIVATE KEY----- ?
No, it's an unencrypted key. 

> What is the value of SSLPassPhraseDialog in /etc/httpd/conf.d/ssl.conf?
SSLPassPhraseDialog exec:/usr/libexec/httpd-ssl-pass-dialog


> If the httpd key is not encrypted did you replace it at some point with some 3rd party certificate?
No. I've never touched any certificate on that machine.

Comment 34 Rob Crittenden 2021-03-18 14:57:38 UTC

I don't understand how this is not encrypted and yet it is tracked as encrypted. Either way your best bet is to go ahead and re-encrypt the file as it is what IPA expects.

Before you begin back up /var/lib/ipa.

You'll need to create /var/lib/ipa/passwds/my.ipa.server-443-RSA with a strong random passphrase.

Then convert to an encrypted key. I output as a separate file for safety, then move the file over top of the original. 

# openssl rsa -in /var/lib/ipa/private/httpd.key -out /var/lib/ipa/private/httpd-new.key -aes128
# mv /var/lib/ipa/private/httpd-new.key /var/lib/ipa/private/httpd.key

Use the passphrase you just created to encrypt it.

And for safety and sanity
# restorecon /var/lib/ipa/private/httpd.key
# chown root:root /var/lib/ipa/private/httpd.key
# chmod 0600 /var/lib/ipa/private/httpd.key

I'd suggest restarting certmonger next. The cert doesn't need renewal so the NEED_KEY_GEN_PIN may be a side-effect of it being unable to unlock the private key. It should go into the state MONITORING.

Comment 35 Thomas Höll 2021-03-18 16:24:47 UTC

Unfortunately, that didn't work. After executing all those steps the certificate goes in SUBMITTING state:

Request ID '20210223071727':
	status: SUBMITTING
	stuck: no
	key pair storage: type=FILE,location='/var/lib/ipa/private/httpd.key',pinfile='/var/lib/ipa/passwds/my.ipa.server-443-RSA'
	certificate: type=FILE,location='/var/lib/ipa/certs/httpd.crt'
	CA: IPA
	issuer: CN=Certificate Authority,O=MY.IPA.REALM
	subject: CN=my.ipa.server,O=MY.IPA.REALM
	expires: 2022-03-18 13:50:30 CET
	dns: my.ipa.server
	principal name: HTTP/my.ipa.server.REALM
	key usage: digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
	eku: id-kp-serverAuth,id-kp-clientAuth
	profile: caIPAserviceCert
	pre-save command: 
	post-save command: /usr/libexec/ipa/certmonger/restart_httpd
	track: yes
	auto-renew: yes

I've attached the certmonger logs from after restart:

 
Mar 18 16:19:05 my.ipa.server certmonger[1669]: 2021-03-18 16:19:05 [1669] Running enrollment/cadata helper "/usr/libexec/certmonger/ipa-server-guard".
Mar 18 16:19:05 my.ipa.server certmonger[1670]: 2021-03-18 16:19:05 [1670] Running enrollment/cadata helper "/usr/libexec/certmonger/ipa-server-guard".
Mar 18 16:19:05 my.ipa.server certmonger[1671]: 2021-03-18 16:19:05 [1671] Running enrollment/cadata helper "/usr/libexec/certmonger/ipa-server-guard".
Mar 18 16:19:05 my.ipa.server certmonger[1672]: 2021-03-18 16:19:05 [1672] Running enrollment/cadata helper "/usr/libexec/certmonger/ipa-server-guard".
Mar 18 16:19:05 my.ipa.server certmonger[1673]: 2021-03-18 16:19:05 [1673] Running enrollment/cadata helper "/usr/libexec/certmonger/ipa-server-guard".
Mar 18 16:19:05 my.ipa.server certmonger[1674]: 2021-03-18 16:19:05 [1674] Running enrollment/cadata helper "/usr/libexec/certmonger/ipa-server-guard".
Mar 18 16:19:05 my.ipa.server certmonger[1675]: 2021-03-18 16:19:05 [1675] Running enrollment/cadata helper "/usr/libexec/certmonger/ipa-server-guard".
Mar 18 16:19:05 my.ipa.server certmonger[1676]: 2021-03-18 16:19:05 [1676] Running enrollment/cadata helper "/usr/libexec/certmonger/ipa-server-guard".
Mar 18 16:19:05 my.ipa.server certmonger[1677]: 2021-03-18 16:19:05 [1677] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1678]: 2021-03-18 16:19:05 [1678] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1679]: 2021-03-18 16:19:05 [1679] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1680]: 2021-03-18 16:19:05 [1680] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1681]: 2021-03-18 16:19:05 [1681] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1682]: 2021-03-18 16:19:05 [1682] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1683]: 2021-03-18 16:19:05 [1683] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1684]: 2021-03-18 16:19:05 [1684] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1685]: 2021-03-18 16:19:05 [1685] Running enrollment/cadata helper "/usr/libexec/certmonger/local-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1686]: 2021-03-18 16:19:05 [1686] Running enrollment/cadata helper "/usr/libexec/certmonger/local-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1687]: 2021-03-18 16:19:05 [1687] Running enrollment/cadata helper "/usr/libexec/certmonger/local-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1688]: 2021-03-18 16:19:05 [1688] Running enrollment/cadata helper "/usr/libexec/certmonger/local-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1689]: 2021-03-18 16:19:05 [1689] Running enrollment/cadata helper "/usr/libexec/certmonger/local-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1690]: 2021-03-18 16:19:05 [1690] Running enrollment/cadata helper "/usr/libexec/certmonger/local-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1691]: 2021-03-18 16:19:05 [1691] Running enrollment/cadata helper "/usr/libexec/certmonger/local-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1692]: 2021-03-18 16:19:05 [1692] Running enrollment/cadata helper "/usr/libexec/certmonger/local-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1693]: 2021-03-18 16:19:05 [1693] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1694]: 2021-03-18 16:19:05 [1694] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1695]: 2021-03-18 16:19:05 [1695] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1696]: 2021-03-18 16:19:05 [1696] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1697]: 2021-03-18 16:19:05 [1697] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:05 my.ipa.server certmonger[1698]: 2021-03-18 16:19:05 [1698] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1699]: 2021-03-18 16:19:06 [1699] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1700]: 2021-03-18 16:19:06 [1700] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1701]: 2021-03-18 16:19:06 [1701] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1702]: 2021-03-18 16:19:06 [1702] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1703]: 2021-03-18 16:19:06 [1703] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1704]: 2021-03-18 16:19:06 [1704] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1705]: 2021-03-18 16:19:06 [1705] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1706]: 2021-03-18 16:19:06 [1706] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1707]: 2021-03-18 16:19:06 [1707] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1708]: 2021-03-18 16:19:06 [1708] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1709]: 2021-03-18 16:19:06 [1709] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1710]: 2021-03-18 16:19:06 [1710] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server dogtag-ipa-renew-agent-submit[1679]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 18 16:19:06 my.ipa.server certmonger[1711]: 2021-03-18 16:19:06 [1711] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1679]: Error opening "/etc/httpd/alias/pwdfile.txt": No such file or directory.
Mar 18 16:19:06 my.ipa.server certmonger[1713]: 2021-03-18 16:19:06 [1713] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1714]: 2021-03-18 16:19:06 [1714] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1716]: 2021-03-18 16:19:06 [1716] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1717]: 2021-03-18 16:19:06 [1717] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1718]: 2021-03-18 16:19:06 [1718] Running enrollment/cadata helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1719]: 2021-03-18 16:19:06 [1719] Setting "CERTMONGER_REQ_SUBJECT" to "CN=KRA Audit,O=MY.IPA.REALM" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1719]: 2021-03-18 16:19:06 [1719] Setting "CERTMONGER_OPERATION" to "SUBMIT" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1719]: 2021-03-18 16:19:06 [1719] Setting "CERTMONGER_CSR" to "-----BEGIN NEW CERTIFICATE REQUEST-----
Mar 18 16:19:06 my.ipa.server certmonger[1719]: -----END NEW CERTIFICATE REQUEST-----
Mar 18 16:19:06 my.ipa.server certmonger[1719]: " for child.
Mar 18 16:19:06 my.ipa.server certmonger[1719]: 2021-03-18 16:19:06 [1719] Setting "CERTMONGER_SPKAC" to "MIIXXXXX==" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1719]: 2021-03-18 16:19:06 [1719] Setting "CERTMONGER_SPKI" to "MIIXXXX" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1719]: 2021-03-18 16:19:06 [1719] Setting "CERTMONGER_LOCAL_CA_DIR" to "/var/lib/certmonger/local" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1719]: 2021-03-18 16:19:06 [1719] Setting "CERTMONGER_KEY_TYPE" to "RSA" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1719]: 2021-03-18 16:19:06 [1719] Setting "CERTMONGER_CA_NICKNAME" to "dogtag-ipa-ca-renew-agent" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1719]: 2021-03-18 16:19:06 [1719] Setting "CERTMONGER_CA_PROFILE" to "caInternalAuthAuditSigningCert" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1719]: 2021-03-18 16:19:06 [1719] Setting "CERTMONGER_CERTIFICATE" to "-----BEGIN CERTIFICATE-----z
Mar 18 16:19:06 my.ipa.server certmonger[1719]: -----END CERTIFICATE-----
Mar 18 16:19:06 my.ipa.server certmonger[1719]: " for child.
Mar 18 16:19:06 my.ipa.server certmonger[1719]: 2021-03-18 16:19:06 [1719] Redirecting stdin to /dev/null, leaving stdout and stderr open for child "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1719]: 2021-03-18 16:19:06 [1719] Running enrollment helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1720]: 2021-03-18 16:19:06 [1720] Setting "CERTMONGER_REQ_SUBJECT" to "CN=KRA Transport Certificate,O=MY.IPA.REALM" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1720]: 2021-03-18 16:19:06 [1720] Setting "CERTMONGER_OPERATION" to "SUBMIT" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1720]: 2021-03-18 16:19:06 [1720] Setting "CERTMONGER_CSR" to "-----BEGIN NEW CERTIFICATE REQUEST-----
Mar 18 16:19:06 my.ipa.server certmonger[1720]: -----END NEW CERTIFICATE REQUEST-----
Mar 18 16:19:06 my.ipa.server certmonger[1720]: " for child.
Mar 18 16:19:06 my.ipa.server certmonger[1720]: 2021-03-18 16:19:06 [1720] Setting "CERTMONGER_SPKAC" to "MIIXXXXX==" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1720]: 2021-03-18 16:19:06 [1720] Setting "CERTMONGER_SPKI" to "MIIXXXXX" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1720]: 2021-03-18 16:19:06 [1720] Setting "CERTMONGER_LOCAL_CA_DIR" to "/var/lib/certmonger/local" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1720]: 2021-03-18 16:19:06 [1720] Setting "CERTMONGER_KEY_TYPE" to "RSA" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1720]: 2021-03-18 16:19:06 [1720] Setting "CERTMONGER_CA_NICKNAME" to "dogtag-ipa-ca-renew-agent" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1720]: 2021-03-18 16:19:06 [1720] Setting "CERTMONGER_CA_PROFILE" to "caInternalAuthTransportCert" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1720]: 2021-03-18 16:19:06 [1720] Setting "CERTMONGER_CERTIFICATE" to "-----BEGIN CERTIFICATE-----
Mar 18 16:19:06 my.ipa.server certmonger[1720]: -----END CERTIFICATE-----
Mar 18 16:19:06 my.ipa.server certmonger[1720]: " for child.
Mar 18 16:19:06 my.ipa.server certmonger[1720]: 2021-03-18 16:19:06 [1720] Redirecting stdin to /dev/null, leaving stdout and stderr open for child "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1720]: 2021-03-18 16:19:06 [1720] Running enrollment helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1721]: 2021-03-18 16:19:06 [1721] Setting "CERTMONGER_REQ_SUBJECT" to "CN=KRA Storage Certificate,O=MY.IPA.REALM" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1721]: 2021-03-18 16:19:06 [1721] Setting "CERTMONGER_OPERATION" to "SUBMIT" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1721]: 2021-03-18 16:19:06 [1721] Setting "CERTMONGER_CSR" to "-----BEGIN NEW CERTIFICATE REQUEST-----
Mar 18 16:19:06 my.ipa.server certmonger[1721]: -----END NEW CERTIFICATE REQUEST-----
Mar 18 16:19:06 my.ipa.server certmonger[1721]: " for child.
Mar 18 16:19:06 my.ipa.server certmonger[1721]: 2021-03-18 16:19:06 [1721] Setting "CERTMONGER_SPKAC" to "MIIXXXXX==" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1721]: 2021-03-18 16:19:06 [1721] Setting "CERTMONGER_SPKI" to "MIIXXXXX" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1721]: 2021-03-18 16:19:06 [1721] Setting "CERTMONGER_LOCAL_CA_DIR" to "/var/lib/certmonger/local" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1721]: 2021-03-18 16:19:06 [1721] Setting "CERTMONGER_KEY_TYPE" to "RSA" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1721]: 2021-03-18 16:19:06 [1721] Setting "CERTMONGER_CA_NICKNAME" to "dogtag-ipa-ca-renew-agent" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1721]: 2021-03-18 16:19:06 [1721] Setting "CERTMONGER_CA_PROFILE" to "caInternalAuthDRMstorageCert" for child.
Mar 18 16:19:06 my.ipa.server certmonger[1721]: 2021-03-18 16:19:06 [1721] Setting "CERTMONGER_CERTIFICATE" to "-----BEGIN CERTIFICATE-----
Mar 18 16:19:06 my.ipa.server certmonger[1721]: " for child.
Mar 18 16:19:06 my.ipa.server certmonger[1721]: 2021-03-18 16:19:06 [1721] Redirecting stdin to /dev/null, leaving stdout and stderr open for child "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1721]: 2021-03-18 16:19:06 [1721] Running enrollment helper "/usr/libexec/certmonger/dogtag-ipa-ca-renew-agent-submit".
Mar 18 16:19:06 my.ipa.server certmonger[1723]: 2021-03-18 16:19:06 [1723] Certificate "Local Signing Authority" valid for 29519368s.
Mar 18 16:19:06 my.ipa.server certmonger[1723]: 2021-03-18 16:19:06 [1723] Certificate "Local Signing Authority 2" valid for 12176934s.
Mar 18 16:19:06 my.ipa.server certmonger[1723]: 2021-03-18 16:19:06 [1723] Certificate "Local Signing Authority 3" no longer valid.
Mar 18 16:19:06 my.ipa.server certmonger[1723]: 2021-03-18 16:19:06 [1723] Certificate "Local Signing Authority 4" no longer valid.
Mar 18 16:19:06 my.ipa.server certmonger[1723]: 2021-03-18 16:19:06 [1723] Certificate "Local Signing Authority 5" no longer valid.
Mar 18 16:19:06 my.ipa.server certmonger[1723]: 2021-03-18 16:19:06 [1723] Certificate "Local Signing Authority 6" no longer valid.
Mar 18 16:19:06 my.ipa.server certmonger[1723]: 2021-03-18 16:19:06 [1723] Certificate "Local Signing Authority 7" no longer valid.
Mar 18 16:19:06 my.ipa.server certmonger[1723]: 2021-03-18 16:19:06 [1723] Certificate "Local Signing Authority 8" no longer valid.
Mar 18 16:19:06 my.ipa.server certmonger[1723]: 2021-03-18 16:19:06 [1723] Certificate "Local Signing Authority 9" no longer valid.
Mar 18 16:19:08 my.ipa.server certmonger[1668]: 2021-03-18 16:19:08 [1668] Error opening key file "/var/lib/ipa/private/httpd.key" for writing: File exists.
Mar 18 16:19:08 my.ipa.server certmonger[1668]: 2021-03-18 16:19:08 [1668] Attempting to open key file "/var/lib/ipa/private/httpd.key.n7u0gZ4b.key" for writing.
Mar 18 16:19:09 my.ipa.server certmonger[1726]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock
Mar 18 16:19:09 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Setting "CERTMONGER_REQ_SUBJECT" to "CN=my.ipa.server,O=MY.IPA.REALM" for child.
Mar 18 16:19:09 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Setting "CERTMONGER_REQ_HOSTNAME" to "my.ipa.server
Mar 18 16:19:09 my.ipa.server certmonger[1729]: ipa-ca.MY.IPA.REALM" for child.
Mar 18 16:19:09 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Setting "CERTMONGER_REQ_PRINCIPAL" to "HTTP/my.ipa.server.REALM" for child.
Mar 18 16:19:09 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Setting "CERTMONGER_OPERATION" to "SUBMIT" for child.
Mar 18 16:19:09 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Setting "CERTMONGER_CSR" to "-----BEGIN NEW CERTIFICATE REQUEST-----
Mar 18 16:19:09 my.ipa.server certmonger[1729]: -----END NEW CERTIFICATE REQUEST-----
Mar 18 16:19:09 my.ipa.server certmonger[1729]: " for child.
Mar 18 16:19:10 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Setting "CERTMONGER_SPKAC" to "MIIXXXXX" for child.
Mar 18 16:19:10 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Setting "CERTMONGER_SPKI" to "MIIXXXXX" for child.
Mar 18 16:19:10 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Setting "CERTMONGER_LOCAL_CA_DIR" to "/var/lib/certmonger/local" for child.
Mar 18 16:19:10 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Setting "CERTMONGER_KEY_TYPE" to "RSA" for child.
Mar 18 16:19:10 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Setting "CERTMONGER_CA_NICKNAME" to "IPA" for child.
Mar 18 16:19:10 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Setting "CERTMONGER_CA_PROFILE" to "caIPAserviceCert" for child.
Mar 18 16:19:10 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Setting "CERTMONGER_CERTIFICATE" to "-----BEGIN CERTIFICATE-----
Mar 18 16:19:10 my.ipa.server certmonger[1729]: -----END CERTIFICATE-----
Mar 18 16:19:10 my.ipa.server certmonger[1729]: " for child.
Mar 18 16:19:10 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Redirecting stdin to /dev/null, leaving stdout and stderr open for child "/usr/libexec/certmonger/ipa-server-guard".
Mar 18 16:19:10 my.ipa.server certmonger[1729]: 2021-03-18 16:19:09 [1729] Running enrollment helper "/usr/libexec/certmonger/ipa-server-guard".
Mar 18 16:19:32 my.ipa.server ipa-submit[1731]: GSSAPI client step 1
Mar 18 16:19:32 my.ipa.server ipa-submit[1731]: GSSAPI client step 1
Mar 18 16:19:39 my.ipa.server ipa-submit[1731]: GSSAPI client step 1
Mar 18 16:19:39 my.ipa.server ipa-submit[1731]: GSSAPI client step 1
Mar 18 16:19:39 my.ipa.server ipa-submit[1731]: GSSAPI client step 2
Mar 18 16:19:41 my.ipa.server certmonger[1733]: 2021-03-18 16:19:41 [1733] Certificate "MY.IPA.REALM IPA CA" valid for 558245010s.
Mar 18 16:19:50 my.ipa.server dogtag-ipa-ca-renew-agent-submit[1721]: Forwarding request to dogtag-ipa-renew-agent
Mar 18 16:19:51 my.ipa.server dogtag-ipa-renew-agent-submit[1740]: usr/lib/api/apiutil.c Could not open /run/lock/opencryptoki/LCK..APIlock

Also, there are a lot of empty files in /var/lib/ipa/private:

-rw------- 1 root root 1704 Mar 17  2020  httpd.key
-rw------- 1 root root    0 Mar 14 18:02  httpd.key.289q_7eC.key
-rw------- 1 root root    0 Oct 25 11:04  httpd.key.3raYbh95.key
-rw------- 1 root root    0 Aug  6  2020  httpd.key.5DrpNov1.key
-rw------- 1 root root    0 Jul 29  2020 'httpd.key.As=5BRU7.key'
-rw------- 1 root root    0 Oct  9 09:01  httpd.key.B6p5tIIC.key
-rw------- 1 root root    0 Oct 25 10:02  httpd.key.ElfTRBtS.key
-rw------- 1 root root    0 Feb 25 14:26  httpd.key.GhHAYhKX.key
-rw------- 1 root root    0 Oct 25 00:13  httpd.key.i06xGfZW.key
-rw------- 1 root root 1874 Mar 18 16:53 'httpd.key.i86HiOb=.key'
-rw------- 1 root root    0 Oct  9 09:09  httpd.key.Ik0APSOu.key
-rw------- 1 root root    0 Oct 25 11:15  httpd.key.JqOC9H4p.key
-rw------- 1 root root    0 Sep 22 15:09  httpd.key.K3OMEsLB.key
-rw------- 1 root root    0 Sep  6  2020  httpd.key.kb94pAf1.key
-rw------- 1 root root    0 Feb 23 09:18  httpd.key.kY6jlVqL.key
-rw------- 1 root root    0 Jul 29  2020 'httpd.key.oDW=i66U.key'
-rw------- 1 root root    0 Sep  6  2020  httpd.key.ogKRW_4B.key
-rw------- 1 root root    0 Mar 14 16:38  httpd.key.qBEw9Nmp.key
-rw------- 1 root root    0 Oct  9 09:18  httpd.key.QdcApLeF.key
-rw------- 1 root root    0 Sep  4  2020  httpd.key.QDyzsG_P.key
-rw------- 1 root root    0 Sep  6  2020  httpd.key.rCdSzqKJ.key
-rw------- 1 root root    0 Mar 18 16:49  httpd.key.RDQ9FZO0.key
-rw------- 1 root root    0 Feb 23 10:36  httpd.key.s1IEas_e.key
-rw------- 1 root root    0 Oct 25 11:21  httpd.key.sctnNAZA.key
-rw------- 1 root root    0 Mar 14 17:53  httpd.key.TaKERq5W.key
-rw------- 1 root root    0 Oct 25 00:02  httpd.key.TDgO9q86.key
-rw------- 1 root root    0 Oct 25 10:05  httpd.key.UgaqTOrl.key
-rw------- 1 root root    0 Sep  6  2020  httpd.key.VxtvQJKo.key
-rw------- 1 root root    0 Sep  6  2020 'httpd.key.Y4=Zk1K8.key'
-rw------- 1 root root    0 Feb 25 10:13  httpd.key.YBtXP5Qz.key
-rw------- 1 root root    0 Oct 25 09:52  httpd.key.Yp6Ax6NE.key
-rw------- 1 root root    0 Sep 22 15:19  httpd.key.ZVYt41rG.key
-rw------- 1 root root 1766 Mar 18 16:52  httpd-new.key

Comment 36 Florence Blanc-Renaud 2021-03-26 08:48:00 UTC

Hi,
there is something strange in your certmonger logs:
Mar 18 16:19:06 my.ipa.server certmonger[1679]: Error opening "/etc/httpd/alias/pwdfile.txt": No such file or directory.

This file was used when httpd was still using the NSS database /etc/httpd/alias to store its Server-Cert.
The recent versions of IPA configure mod_ssl instead of mod_nss and the cert/key are stored in files /var/lib/ipa/certs/httpd.crt / /var/lib/ipa/private/httpd.key

So maybe the migration from nss to ssl didn't go so well. Can you check if there is anything in /var/log/ipaupgrade.log (around the line [Migrating from mod_nss to mod_ssl])?

Also I want to double-check with you, if your hostname is not my.ipa.server, the pin file name needs to be adapted: /var/lib/ipa/passwds/my.ipa.server-443-RSA should be replaced with ./var/lib/ipa/passwds/<server fqdn>-443-RSA.

Comment 37 Rob Crittenden 2021-03-26 12:36:38 UTC

Flo, the "/etc/httpd/alias/pwdfile.txt" is a red herring. It's still in certmonger to support older versions of RHEL though it was recently removed upstream. It is not likely to be an issue here.

According to the log a CSR was generated and submitted and a certificate issued.

Comment 38 Thomas Höll 2021-03-29 13:18:44 UTC

(In reply to Florence Blanc-Renaud from comment #36)
> Hi,
> there is something strange in your certmonger logs:
> Mar 18 16:19:06 my.ipa.server certmonger[1679]: Error opening
> "/etc/httpd/alias/pwdfile.txt": No such file or directory.
> 
> This file was used when httpd was still using the NSS database
> /etc/httpd/alias to store its Server-Cert.
> The recent versions of IPA configure mod_ssl instead of mod_nss and the
> cert/key are stored in files /var/lib/ipa/certs/httpd.crt /
> /var/lib/ipa/private/httpd.key
> 
> So maybe the migration from nss to ssl didn't go so well. Can you check if
> there is anything in /var/log/ipaupgrade.log (around the line [Migrating
> from mod_nss to mod_ssl])?

Unfortunately, my logs don't reach back that far. IIRC, the migration itself went fine, but I hat to manually disable mod_nss. Otherwise, httpd didn't start.

> 
> Also I want to double-check with you, if your hostname is not my.ipa.server,
> the pin file name needs to be adapted:
> /var/lib/ipa/passwds/my.ipa.server-443-RSA should be replaced with
> ./var/lib/ipa/passwds/<server fqdn>-443-RSA.

Correct.

Note You need to log in before you can comment on or make changes to this bug.

abokovoy
alee
ascheel
cfu
edewata
fdc
frenaud
ipa-maint
jcholast
jhrozek
kwright
mharmsen
mhjacks
mkosek
pvoborni
rcritten
ssorce
thomas
twoerner
wdh