Bug 1173207

Summary: IPA certs fail to autorenew simultaneouly
Product: Red Hat Enterprise Linux 7 Reporter: Scott Poore <spoore>
Component: ipaAssignee: IPA Maintainers <ipa-maint>
Status: CLOSED ERRATA QA Contact: Namita Soman <nsoman>
Severity: unspecified Docs Contact:
Priority: medium    
Version: 7.1CC: jcholast, nalin, ovasik, rcritten
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: ipa-4.1.0-14.el7 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-03-05 10:18:57 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
pki debug log
none
all of /var/log none

Description Scott Poore 2014-12-11 16:50:20 UTC 
Description of problem:

Testing IPA CA Certificate autorenewal I am seeing certificate autorenewal fail because it's trying to renew everything at the same time.

Version-Release number of selected component (if applicable):
ipa-server-4.1.0-12.el7.x86_64
certmonger-0.75.14-2.el7.x86_64
pki-ca-10.1.2-5.el7.noarch


How reproducible:
always

Steps to Reproduce:

1.  Setup IPA server

ipa-server-install --setup-dns --forwarder=<IP> -r <REALM> -a <PASSWORD> -p <PASSWORD> -U

2.  Walk the time forward till you reach the CA Certificate renewal threshold.

getcert list | egrep "status|expires|Request|subject|ca-error"
date -u <soonest expiration date - 4 weeks>
# check with getcert until everything back in monitoring then repeat

3.  When you reach time for CA expire, all certs should show same expiration equal to that of CA certificate's.  

4.  Change time to within 4 weeks of expiration.


Actual results:

[root@vm1 ~]# date -u; getcert list | egrep "status|expires|Request|subject|ca-error"
Mon Nov 13 15:06:03 UTC 2034
Request ID '20141211150642':
	status: NOTIFYING_VALIDITY
	subject: CN=CA Audit,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150643':
	status: NOTIFYING_VALIDITY
	subject: CN=OCSP Subsystem,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150644':
	status: NOTIFYING_VALIDITY
	subject: CN=CA Subsystem,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150645':
	status: NOTIFYING_VALIDITY
	subject: CN=Certificate Authority,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150646':
	status: NOTIFYING_VALIDITY
	subject: CN=IPA RA,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150647':
	status: GENERATING_CSR
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150648':
	status: GENERATING_CSR
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150715':
	status: GENERATING_CSR
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC

[root@vm1 ~]# date -u; getcert list | egrep "status|expires|Request|subject|ca-error"
Mon Nov 13 15:06:46 UTC 2034
Request ID '20141211150642':
	status: CA_UNREACHABLE
	ca-error: Internal error
	subject: CN=CA Audit,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150643':
	status: CA_UNREACHABLE
	ca-error: Internal error
	subject: CN=OCSP Subsystem,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150644':
	status: CA_UNREACHABLE
	ca-error: Internal error
	subject: CN=CA Subsystem,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150645':
	status: CA_UNREACHABLE
	ca-error: Internal error
	subject: CN=Certificate Authority,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150646':
	status: CA_UNREACHABLE
	ca-error: Internal error
	subject: CN=IPA RA,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150647':
	status: CA_UNREACHABLE
	ca-error: Error 7 connecting to http://vm1.example.test:8080/ca/ee/ca/profileSubmit: Couldn't connect to server.
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150648':
	status: CA_UNREACHABLE
	ca-error: Error setting up ccache for "host" service on client using default keytab: Cannot contact any KDC for realm 'EXAMPLE.TEST'.
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150715':
	status: CA_UNREACHABLE
	ca-error: Error setting up ccache for "host" service on client using default keytab: Cannot contact any KDC for realm 'EXAMPLE.TEST'.
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC

Expected results:

CA Certificate renews first, then others in proper order to prevent CA_UNREACHABLE due to conflicts with renewing some at the same time.

Additional info:
I'll also attach the PKI debug log.
Comment 2 Scott Poore 2014-12-11 17:09:10 UTC 
Created attachment 967330 [details]
pki debug log

Unfortunately I had truncated the previous test run debug log.  Here's a second run though.

[root@vm1 ~]# date -u; getcert list | egrep "status|expires|Request|subject|ca-error"
Thu Dec 11 17:00:16 UTC 2014
Request ID '20141211150642':
	status: MONITORING
	subject: CN=CA Audit,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150643':
	status: MONITORING
	subject: CN=OCSP Subsystem,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150644':
	status: MONITORING
	subject: CN=CA Subsystem,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150645':
	status: MONITORING
	subject: CN=Certificate Authority,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150646':
	status: MONITORING
	subject: CN=IPA RA,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150647':
	status: MONITORING
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150648':
	status: MONITORING
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150715':
	status: MONITORING
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC

[root@vm1 ~]# date -u 111315062034
Mon Nov 13 15:06:00 UTC 2034

[root@vm1 ~]# date -u; getcert list | egrep "status|expires|Request|subject|ca-error"
Mon Nov 13 15:06:03 UTC 2034
Request ID '20141211150642':
	status: NOTIFYING_VALIDITY
	subject: CN=CA Audit,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150643':
	status: NOTIFYING_VALIDITY
	subject: CN=OCSP Subsystem,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150644':
	status: NOTIFYING_VALIDITY
	subject: CN=CA Subsystem,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150645':
	status: NOTIFYING_VALIDITY
	subject: CN=Certificate Authority,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150646':
	status: NOTIFYING_VALIDITY
	subject: CN=IPA RA,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150647':
	status: GENERATING_CSR
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150648':
	status: GENERATING_CSR
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150715':
	status: GENERATING_CSR
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC


[root@vm1 ~]# date -u; getcert list | egrep "status|expires|Request|subject|ca-error"
Mon Nov 13 15:10:25 UTC 2034
Request ID '20141211150642':
	status: CA_UNREACHABLE
	ca-error: Internal error
	subject: CN=CA Audit,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150643':
	status: CA_UNREACHABLE
	ca-error: Internal error
	subject: CN=OCSP Subsystem,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150644':
	status: CA_UNREACHABLE
	ca-error: Internal error
	subject: CN=CA Subsystem,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150645':
	status: CA_UNREACHABLE
	ca-error: Internal error
	subject: CN=Certificate Authority,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150646':
	status: CA_UNREACHABLE
	ca-error: Internal error
	subject: CN=IPA RA,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150647':
	status: CA_UNREACHABLE
	ca-error: Error 7 connecting to http://vm1.example.test:8080/ca/ee/ca/profileSubmit: Couldn't connect to server.
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150648':
	status: CA_UNREACHABLE
	ca-error: Error setting up ccache for "host" service on client using default keytab: Cannot contact any KDC for realm 'EXAMPLE.TEST'.
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Request ID '20141211150715':
	status: CA_UNREACHABLE
	ca-error: Error setting up ccache for "host" service on client using default keytab: Cannot contact any KDC for realm 'EXAMPLE.TEST'.
	subject: CN=vm1.example.test,O=EXAMPLE.TEST
	expires: 2034-12-11 15:06:02 UTC
Comment 3 Scott Poore 2014-12-11 17:09:45 UTC 
Created attachment 967331 [details]
all of /var/log
Comment 4 Jan Cholasta 2014-12-12 10:12:01 UTC 
Upstream ticket:
https://fedorahosted.org/freeipa/ticket/4803
Comment 5 Jan Cholasta 2015-01-13 18:37:19 UTC 
Fixed upstream
master:
https://fedorahosted.org/freeipa/changeset/6a1304324fe94b17e8dc4a418f90bea028160ace
https://fedorahosted.org/freeipa/changeset/b9ae7690489368ead9f4983d386fa210dc265dfa
ipa-4-1:
https://fedorahosted.org/freeipa/changeset/ff52891615c29adc6b07743f85984d29c1438d38
https://fedorahosted.org/freeipa/changeset/760ebaa6852b12f1d58032b33ef538d9894dc3ef
Comment 7 Scott Poore 2015-01-15 01:16:28 UTC 
Verified.

Version ::

ipa-server-4.1.0-15.el7.x86_64

Results ::

I setup a self-signed install and walked the time forward incrementally until I reached the CA cert expiration threshold.  

 Starting expirations:

[root@vm1 ~]# getcert list | egrep "status|expires|Request|subject|ca-error"
Request ID '20150114194236':
    status: MONITORING
    subject: CN=CA Audit,O=EXAMPLE.TEST
    expires: 2017-01-03 19:42:01 UTC
Request ID '20150114194237':
    status: MONITORING
    subject: CN=OCSP Subsystem,O=EXAMPLE.TEST
    expires: 2017-01-03 19:42:01 UTC
Request ID '20150114194238':
    status: MONITORING
    subject: CN=CA Subsystem,O=EXAMPLE.TEST
    expires: 2017-01-03 19:42:01 UTC
Request ID '20150114194239':
    status: MONITORING
    subject: CN=Certificate Authority,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194240':
    status: MONITORING
    subject: CN=IPA RA,O=EXAMPLE.TEST
    expires: 2017-01-03 19:42:35 UTC
Request ID '20150114194241':
    status: MONITORING
    subject: CN=vm1.example.test,O=EXAMPLE.TEST
    expires: 2017-01-03 19:42:01 UTC
Request ID '20150114194242':
    status: MONITORING
    subject: CN=vm1.example.test,O=EXAMPLE.TEST
    expires: 2017-01-14 19:42:42 UTC
Request ID '20150114194304':
    status: MONITORING
    subject: CN=vm1.example.test,O=EXAMPLE.TEST
    expires: 2017-01-14 19:43:03 UTC

[root@vm1 ~]# date
Wed Jan 14 13:46:08 CST 2015


After walking time forward, I stopped right before the last step forward in time to capture a stable state:

[root@vm1 ~]# g
Request ID '20150114194236':
    status: MONITORING
    subject: CN=CA Audit,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194237':
    status: MONITORING
    subject: CN=OCSP Subsystem,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194238':
    status: MONITORING
    subject: CN=CA Subsystem,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194239':
    status: MONITORING
    subject: CN=Certificate Authority,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194240':
    status: MONITORING
    subject: CN=IPA RA,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194241':
    status: MONITORING
    subject: CN=vm1.example.test,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194242':
    status: MONITORING
    subject: CN=vm1.example.test,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194304':
    status: MONITORING
    subject: CN=vm1.example.test,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Thu May 4 22:43:43 CDT 2034

And here I can see it attempts to autorenew everything simultaneously:

[root@vm1 ~]# date -u 121919422034
Tue Dec 19 19:42:00 UTC 2034

[root@vm1 ~]# g
Request ID '20150114194236':
    status: NOTIFYING_VALIDITY
    subject: CN=CA Audit,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194237':
    status: NOTIFYING_VALIDITY
    subject: CN=OCSP Subsystem,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194238':
    status: NOTIFYING_VALIDITY
    subject: CN=CA Subsystem,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194239':
    status: NOTIFYING_VALIDITY
    subject: CN=Certificate Authority,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194240':
    status: NOTIFYING_VALIDITY
    subject: CN=IPA RA,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194241':
    status: GENERATING_CSR
    subject: CN=vm1.example.test,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194242':
    status: GENERATING_CSR
    subject: CN=vm1.example.test,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194304':
    status: GENERATING_CSR
    subject: CN=vm1.example.test,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Tue Dec 19 13:42:06 CST 2034

Then wait for a while and check back to see that the CA has renewed and everything is back in MONITORING and nothing fell to CA_UNREACHABLE:

[root@vm1 ~]# sleep 180

[root@vm1 ~]# g
Request ID '20150114194236':
    status: MONITORING
    subject: CN=CA Audit,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194237':
    status: MONITORING
    subject: CN=OCSP Subsystem,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194238':
    status: MONITORING
    subject: CN=CA Subsystem,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194239':
    status: MONITORING
    subject: CN=Certificate Authority,O=EXAMPLE.TEST
    expires: 2054-12-19 19:43:22 UTC
Request ID '20150114194240':
    status: MONITORING
    subject: CN=IPA RA,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194241':
    status: MONITORING
    subject: CN=vm1.example.test,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194242':
    status: MONITORING
    subject: CN=vm1.example.test,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Request ID '20150114194304':
    status: MONITORING
    subject: CN=vm1.example.test,O=EXAMPLE.TEST
    expires: 2035-01-14 19:42:00 UTC
Tue Dec 19 13:46:08 CST 2034
Comment 9 errata-xmlrpc 2015-03-05 10:18:57 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHSA-2015-0442.html