[Freeipa-users] Failure decoding Certificate Signing Request

[Thomson, Ryan]

Hello FreeIPA users and developers,

I'm facing a problem with expired certificates in FreeIPA.

I have searched through the list archives and found advice to stop the IPA service, roll back the system clock to a time when the certs were valid but nearly expired, start IPA and then use certmonger to renew the certs as it normally should (getcert resubmit -i <REQUESTID>). This appears to have worked as expected for the dogtag/CA certificates signed with the "dogtag-ipa-renew-agent" CA but is failing for the HTTP and dirsrv certificates signed with the "IPA" CA.

Certmonger reports the following error (ipa-getcert list):

Server failed request, will retry: 4301 (RPC failed at server.  Certificate operation cannot be completed: Failure decoding Certificate Signing Request).

I turned on IPA debugging to acquire the following error in /var/log/httpd/error_log when resubmitting to certmonger:

[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: WSGI xmlserver.__call__:
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: Created connection context.ldap2
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: raw: cert_request(u'MIIDcDCCAlgCAQAwNjEUMBIGA1UEChMLRk1SSS5VQkMuQ0ExHjAcBgNVBAMTFXNoYW1yb2NrLmJyYWluLnViYy5jYTCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAKCzypT3oNmPx90Tevn/vv8FUouT8UL2d8qmhxK0AUVPxJwoZPtkbQBWzUNxkTBkhWV/5s0hN19VBb5ruHTbeSv7KBX8P+CwopQbbjpaqpwvi3dso1NSnT3kU+cNYY1j4tvyKkwPVS7FrP4oELX+aEEOuGF8eyOPK78UlZtDrY0Npje5l8MsUrRMKqQAjhIFc4EzTb2tqcR8Ch+OzBHugcFXcmXGmFnHkK29z2f7Aq1ynk0SqWC0r7nZXw/17jI1OEeD9pagGH1OLEzMrJUQTrvQGH/W+XPt2+ZvJ3UtF4ltw2ViStiG958b32OQvGnbQVJjaIgjpOSiorfnhM0wCPcCAwEAAaCB9DAaBgkqhkiG9w0BCRQxDRMLU2VydmVyLUNlcnQwgdUGCSqGSIb3DQEJDjGBxzCBxDAOBgNVHQ8BAQAEBAMCBPAwgZkGA1UdEQEBAASBjjCBi6A8BgorBgEEAYI3FAIDoC4MLGRvZ3RhZ2xkYXAvc2hhbXJvY2suYnJhaW4udWJjLmNhQEZNUkkuVUJDLkNBoEsGBisGAQUCAqBBMD+gDRsLRk1SSS5VQkMuQ0GhLjAsoAMCAQGhJTAjGwpkb2d0YWdsZGFwGxVzaGFtcm9jay5icmFpbi51YmMuY2EwFgYDVR0lAQEABAwwCgYIKwYBBQUHAwEwDQYJKoZIhvcNAQELBQADggEBAIP+0+O/COqFwbqUCJ+LJiE8aAmP01SRvfJx/RSE9huquDd2XdHVIQ6lQj6qnQYTtCw2NKRq77R3VmUAiCMpQwI9/x/QaaI4MBvV9iYA8b1H/weyvZAMw1mGkdgY55KWPhBtCqLuxHcGRblrtsy2PGp9wm/834s5YamQky+InQFlDy4o5ox+5U5iZS+pvKm52d0TQTozvZ/gSTAqEc+gpwlGAU4U0VaC+7PYnwkYJ98jLDaALm2OCWnSvw/02NLlc+h02mTjumAQ/YnWYNXiAtUbiA8BAkjT0UGV79Vi/aUKxpBTZQXbldrHN/cAmUtSMxebNNQjyUdzAHEV+TUUP2o=', principal=u'dogtagldap/HOSTNAME.DOMAIN at FULLY.QUALIFIED.DOMAIN', add=True)
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: cert_request(u'MIIDcDCCAlgCAQAwNjEUMBIGA1UEChMLRk1SSS5VQkMuQ0ExHjAcBgNVBAMTFXNoYW1yb2NrLmJyYWluLnViYy5jYTCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAKCzypT3oNmPx90Tevn/vv8FUouT8UL2d8qmhxK0AUVPxJwoZPtkbQBWzUNxkTBkhWV/5s0hN19VBb5ruHTbeSv7KBX8P+CwopQbbjpaqpwvi3dso1NSnT3kU+cNYY1j4tvyKkwPVS7FrP4oELX+aEEOuGF8eyOPK78UlZtDrY0Npje5l8MsUrRMKqQAjhIFc4EzTb2tqcR8Ch+OzBHugcFXcmXGmFnHkK29z2f7Aq1ynk0SqWC0r7nZXw/17jI1OEeD9pagGH1OLEzMrJUQTrvQGH/W+XPt2+ZvJ3UtF4ltw2ViStiG958b32OQvGnbQVJjaIgjpOSiorfnhM0wCPcCAwEAAaCB9DAaBgkqhkiG9w0BCRQxDRMLU2VydmVyLUNlcnQwgdUGCSqGSIb3DQEJDjGBxzCBxDAOBgNVHQ8BAQAEBAMCBPAwgZkGA1UdEQEBAASBjjCBi6A8BgorBgEEAYI3FAIDoC4MLGRvZ3RhZ2xkYXAvc2hhbXJvY2suYnJhaW4udWJjLmNhQEZNUkkuVUJDLkNBoEsGBisGAQUCAqBBMD+gDRsLRk1SSS5VQkMuQ0GhLjAsoAMCAQGhJTAjGwpkb2d0YWdsZGFwGxVzaGFtcm9jay5icmFpbi51YmMuY2EwFgYDVR0lAQEABAwwCgYIKwYBBQUHAwEwDQYJKoZIhvcNAQELBQADggEBAIP+0+O/COqFwbqUCJ+LJiE8aAmP01SRvfJx/RSE9huquDd2XdHVIQ6lQj6qnQYTtCw2NKRq77R3VmUAiCMpQwI9/x/QaaI4MBvV9iYA8b1H/weyvZAMw1mGkdgY55KWPhBtCqLuxHcGRblrtsy2PGp9wm/834s5YamQky+InQFlDy4o5ox+5U5iZS+pvKm52d0TQTozvZ/gSTAqEc+gpwlGAU4U0VaC+7PYnwkYJ98jLDaALm2OCWnSvw/02NLlc+h02mTjumAQ/YnWYNXiAtUbiA8BAkjT0UGV79Vi/aUKxpBTZQXbldrHN/cAmUtSMxebNNQjyUdzAHEV+TUUP2o=', principal=u'dogtagldap/HOSTNAME.DOMAIN at FULLY.QUALIFIED.DOMAIN', request_type=u'pkcs10', add=True)
[Mon Oct 07 00:03:22 2013] [error] ipa: INFO: host/HOSTNAME.DOMAIN at FULLY.QUALIFIED.DOMAIN: cert_request(u'MIIDcDCCAlgCAQAwNjEUMBIGA1UEChMLRk1SSS5VQkMuQ0ExHjAcBgNVBAMTFXNoYW1yb2NrLmJyYWluLnViYy5jYTCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAKCzypT3oNmPx90Tevn/vv8FUouT8UL2d8qmhxK0AUVPxJwoZPtkbQBWzUNxkTBkhWV/5s0hN19VBb5ruHTbeSv7KBX8P+CwopQbbjpaqpwvi3dso1NSnT3kU+cNYY1j4tvyKkwPVS7FrP4oELX+aEEOuGF8eyOPK78UlZtDrY0Npje5l8MsUrRMKqQAjhIFc4EzTb2tqcR8Ch+OzBHugcFXcmXGmFnHkK29z2f7Aq1ynk0SqWC0r7nZXw/17jI1OEeD9pagGH1OLEzMrJUQTrvQGH/W+XPt2+ZvJ3UtF4ltw2ViStiG958b32OQvGnbQVJjaIgjpOSiorfnhM0wCPcCAwEAAaCB9DAaBgkqhkiG9w0BCRQxDRMLU2VydmVyLUNlcnQwgdUGCSqGSIb3DQEJDjGBxzCBxDAOBgNVHQ8BAQAEBAMCBPAwgZkGA1UdEQEBAASBjjCBi6A8BgorBgEEAYI3FAIDoC4MLGRvZ3RhZ2xkYXAvc2hhbXJvY2suYnJhaW4udWJjLmNhQEZNUkkuVUJDLkNBoEsGBisGAQUCAqBBMD+gDRsLRk1SSS5VQkMuQ0GhLjAsoAMCAQGhJTAjGwpkb2d0YWdsZGFwGxVzaGFtcm9jay5icmFpbi51YmMuY2EwFgYDVR0lAQEABAwwCgYIKwYBBQUHAwEwDQYJKoZIhvcNAQELBQADggEBAIP+0+O/COqFwbqUCJ+LJiE8aAmP01SRvfJx/RSE9huquDd2XdHVIQ6lQj6qnQYTtCw2NKRq77R3VmUAiCMpQwI9/x/QaaI4MBvV9iYA8b1H/weyvZAMw1mGkdgY55KWPhBtCqLuxHcGRblrtsy2PGp9wm/834s5YamQky+InQFlDy4o5ox+5U5iZS+pvKm52d0TQTozvZ/gSTAqEc+gpwlGAU4U0VaC+7PYnwkYJ98jLDaALm2OCWnSvw/02NLlc+h02mTjumAQ/YnWYNXiAtUbiA8BAkjT0UGV79Vi/aUKxpBTZQXbldrHN/cAmUtSMxebNNQjyUdzAHEV+TUUP2o=', principal=u'dogtagldap/HOSTNAME.DOMAIN at FULLY.QUALIFIED.DOMAIN', add=True): CertificateOperationError
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: response: CertificateOperationError: Certificate operation cannot be completed: Gettext('3 - Failure decoding Certificate Signing Request', domain='ipa', localedir=None)
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: no session id in request, generating empty session data with id=e943ef07ef510b4519a6f7658d96ae51
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: store session: session_id=e943ef07ef510b4519a6f7658d96ae51 start_timestamp=2013-10-07T00:03:22 access_timestamp=2013-10-07T00:03:22 expiration_timestamp=1969-12-31T16:00:00
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: finalize_kerberos_acquisition: xmlserver ccache_name="FILE:/tmp/krb5cc_apache_fWDfep" session_id="e943ef07ef510b4519a6f7658d96ae51"
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: reading ccache data from file "/tmp/krb5cc_apache_fWDfep"
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: get_credential_times: principal=krbtgt/FULLY.QUALIFIED.DOMAIN at FULLY.QUALIFIED.DOMAIN, authtime=10/07/13 00:03:22, starttime=10/07/13 00:03:22, endtime=10/08/13 00:03:22, renew_till=12/31/69 16:00:00
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: KRB5_CCache FILE:/tmp/krb5cc_apache_fWDfep endtime=1381215802 (10/08/13 00:03:22)
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: set_session_expiration_time: duration_type=inactivity_timeout duration=1200 max_age=1381215502 expiration=1381130602.32 (2013-10-07T00:23:22)
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: store session: session_id=e943ef07ef510b4519a6f7658d96ae51 start_timestamp=2013-10-07T00:03:22 access_timestamp=2013-10-07T00:03:22 expiration_timestamp=2013-10-07T00:23:22
[Mon Oct 07 00:03:22 2013] [error] ipa: DEBUG: Destroyed connection context.ldap2

I briefly spoke with Rob on #freeipa last week and he suggested trying to manually load the certificate signing request in a python shell, roughly as follows:

from ipalib import pkcs10
with open ("req.csr", "r") as myreq:
	csr=myreq.read()
request = pkcs10.load_certificate_request(csr)
print request
print pkcs10.get_subject(request)
print pkcs10.get_subjectaltname(request)

I was able to do this and see the CSR info on stdout, including subject and alt name.

The system is RHEL6.4, fully updated as of today.

Any ideas on where to go from here?

--Ryan