[Freeipa-users] Failure decoding Certificate Signing Request

[Thomson, Ryan]

Hi Rob,

> There is some duplication in the error strings (ticket
> https://fedorahosted.org/freeipa/ticket/3988). Did you add a number prefix
> to yours, I see a 3 -in the error. If so, by my calculation, this works out to be
> an NSPRError. It would be helpful to know what exception is being raised,
> which we don't do.

I did prefix numbers to the various error strings. 

> Either way, if you could enhance each occurrence of 'Failure decoding
> Certificate Signing Request' in /usr/lib/python*/site-
> packages/ipalib/plugins/cert.py to something like:
> 
> except NSPEError, nsprerr:
>      raise  errors.CertificateOperationError(error=_('Failure decoding
> Certificate Signing Request" %s') % nsprerr)
> 
> You'll need to restart the httpd process afterwards. This should give us the
> real reason for the failure.

Done. The error I get now is:

Server failed request, will retry: 4301 (RPC failed at server.  Certificate operation cannot be completed: Failure decoding Certificate Signing Request" [Errno -8018] error (-8018) unknown).

and in /var/log/httpd/error_log:

[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: WSGI xmlserver.__call__:
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: Created connection context.ldap2
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Sat Oct 05 17:51:41 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)
[Sat Oct 05 17:51:41 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)
[Sat Oct 05 17:51:41 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
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: response: CertificateOperationError: Certificate operation cannot be completed: Failure decoding Certificate Signing Request" [Errno -8018] error (-8018) unknown
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: no session id in request, generating empty session data with id=483b62ce1f77f2a678aad6285f1bdb65
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: store session: session_id=483b62ce1f77f2a678aad6285f1bdb65 start_timestamp=2013-10-05T17:51:41 access_timestamp=2013-10-05T17:51:41 expiration_timestamp=1969-12-31T16:00:00
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: finalize_kerberos_acquisition: xmlserver ccache_name="FILE:/tmp/krb5cc_apache_QRaqrv" session_id="483b62ce1f77f2a678aad6285f1bdb65"
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: reading ccache data from file "/tmp/krb5cc_apache_QRaqrv"
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: get_credential_times: principal=krbtgt/FULLY.QUALIFIED.DOMAIN at FULLY.QUALIFIED.DOMAIN, authtime=10/05/13 17:51:41, starttime=10/05/13 17:51:41, endtime=10/06/13 17:51:41, renew_till=12/31/69 16:00:00
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: KRB5_CCache FILE:/tmp/krb5cc_apache_QRaqrv endtime=1381107101 (10/06/13 17:51:41)
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: set_session_expiration_time: duration_type=inactivity_timeout duration=1200 max_age=1381106801 expiration=1381021901.43 (2013-10-05T18:11:41)
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: store session: session_id=483b62ce1f77f2a678aad6285f1bdb65 start_timestamp=2013-10-05T17:51:41 access_timestamp=2013-10-05T17:51:41 expiration_timestamp=2013-10-05T18:11:41
[Sat Oct 05 17:51:41 2013] [error] ipa: DEBUG: Destroyed connection context.ldap2

I know almost nothing about NSS but it seems that error -8018 is also known as "SEC_ERROR_UNKNOWN_PKCS11_ERROR".

> This failure seems unrelated to the CSR itself, which looks fine.

That's what I thought as well but it's nice to hear someone else confirm it!

Thank you,

--Ryan