String index out of range: -36

Hello all,

This i my first post here, so be gentle.

I'm running FreeIPA 4.4.0-14 (ipa-server-4.4.0-14.el7.centos.7.x86_64) on CentOS 7.3.1611 and since a while i can't get any certificates to my hosts.

The client has installed: ipa-client-4.4.0-14.el7.centos.7.x86_64 ans is also running CentOS 7.3.1611 (actually, this happens on all new clients, same os, same version).

I'm running 'ipa-getcert request -f /etc/pki/tls/certs/servername.crt -k /etc/pki/tls/private/servername.key' on the client. This runs without any errors. When i look at the output of 'ipa-getcert list' i get:

Request ID '20170610005114':
status: CA_UNREACHABLE
ca-error: Server at https://freeipa.crossyn.local/ipa/xml failed request, will retry: 4301 (RPC failed at server.  Certificate operation cannot be completed: FAILURE (String index out of range: -36)).
stuck: no
key pair storage: type=FILE,location='/etc/pki/tls/private/servername.key'
certificate: type=FILE,location='/etc/pki/tls/certs/servername.crt'
CA: IPA
issuer: 
subject: 
expires: unknown
pre-save command: 
post-save command: 
track: yes
auto-renew: yes

On the FreeIPA server i noticed in /var/log/httpd/error_log: 
[Sat Jun 10 02:51:15.230313 2017] [:error] [pid 7199] ipa: ERROR: ra.request_certificate(): FAILURE (String index out of range: -36)
[Sat Jun 10 02:51:15.230621 2017] [:error] [pid 7199] ipa: INFO: [xmlserver] host/<hostname removed>: cert_request(<removed certificate for security reasons>', principal=u'host/<hostname removed>', add=True, version=u'2.51'): CertificateOperationError

Any thoughts on how to fix this? Or debug this further? This i a single FreeIPA server with no replica's. When this is fixed i'm going to add a replica but i don't think i can do that without fixing this.

Best regards,

Jochem Kuijpers

[Rob Crittenden]

jochem--- via FreeIPA-users wrote:
> Hello all,
>
> This i my first post here, so be gentle.
>
> I'm running FreeIPA 4.4.0-14 (ipa-server-4.4.0-14.el7.centos.7.x86_64) on CentOS 7.3.1611 and since a while i can't get any certificates to my hosts.
>
> The client has installed: ipa-client-4.4.0-14.el7.centos.7.x86_64 ans is also running CentOS 7.3.1611 (actually, this happens on all new clients, same os, same version).
>
> I'm running 'ipa-getcert request -f /etc/pki/tls/certs/servername.crt -k /etc/pki/tls/private/servername.key' on the client. This runs without any errors. When i look at the output of 'ipa-getcert list' i get:
>
> Request ID '20170610005114':
> status: CA_UNREACHABLE
> ca-error: Server at https://freeipa.crossyn.local/ipa/xml failed request, will retry: 4301 (RPC failed at server.  Certificate operation cannot be completed: FAILURE (String index out of range: -36)).
> stuck: no
> key pair storage: type=FILE,location='/etc/pki/tls/private/servername.key'
> certificate: type=FILE,location='/etc/pki/tls/certs/servername.crt'
> CA: IPA
> issuer: 
> subject: 
> expires: unknown
> pre-save command: 
> post-save command: 
> track: yes
> auto-renew: yes
>
> On the FreeIPA server i noticed in /var/log/httpd/error_log: 
> [Sat Jun 10 02:51:15.230313 2017] [:error] [pid 7199] ipa: ERROR: ra.request_certificate(): FAILURE (String index out of range: -36)
> [Sat Jun 10 02:51:15.230621 2017] [:error] [pid 7199] ipa: INFO: [xmlserver] host/<hostname removed>: cert_request(<removed certificate for security reasons>', principal=u'host/<hostname removed>', add=True, version=u'2.51'): CertificateOperationError
>
> Any thoughts on how to fix this? Or debug this further? This i a single FreeIPA server with no replica's. When this is fixed i'm going to add a replica but i don't think i can do that without fixing this.

I suspect this error is coming from the CA itself. I'd try this, it
might give more info.

Create /etc/ipa/server.conf with the contents:

[global]
debut = True

Then restart httpd and do your request again. It should log more steps
in the apache error log.

You might also look at /var/log/pki/pki-tomcat/ca/debug

rob
> Best regards,
>
> Jochem Kuijpers
> _______________________________________________
> FreeIPA-users mailing list -- [e-mail]
> To unsubscribe send an email to [e-mail]

Rob,

Thank you for replying. I've enable debug and i think this is the relevant portion of the log.

[Sat Jun 10 04:18:58.109402 2017] [:error] [pid 11081] ipa: DEBUG: NSSConnection init freeipa.fakedomain.local
[Sat Jun 10 04:18:58.271640 2017] [:error] [pid 11081] ipa: DEBUG: Connecting: 192.168.0.10:0
[Sat Jun 10 04:18:58.281333 2017] [:error] [pid 11081] ipa: DEBUG: approved_usage = SSL Server intended_usage = SSL Server
[Sat Jun 10 04:18:58.281432 2017] [:error] [pid 11081] ipa: DEBUG: cert valid True for "CN=freeipa.fakedomain.local,O=fakedomain.LOCAL"
[Sat Jun 10 04:18:58.285331 2017] [:error] [pid 11081] ipa: DEBUG: handshake complete, peer = 192.168.0.10:443
[Sat Jun 10 04:18:58.285406 2017] [:error] [pid 11081] ipa: DEBUG: Protocol: TLS1.2
[Sat Jun 10 04:18:58.285459 2017] [:error] [pid 11081] ipa: DEBUG: Cipher: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
[Sat Jun 10 04:18:58.292610 2017] [:error] [pid 11081] ipa: DEBUG: approved_usage = SSL Server intended_usage = SSL Server
[Sat Jun 10 04:18:58.292691 2017] [:error] [pid 11081] ipa: DEBUG: cert valid True for "CN=freeipa.fakedomain.local,O=fakedomain.LOCAL"
[Sat Jun 10 04:18:58.303693 2017] [:error] [pid 11081] ipa: DEBUG: handshake complete, peer = 192.168.0.10:443
[Sat Jun 10 04:18:58.303756 2017] [:error] [pid 11081] ipa: DEBUG: Protocol: TLS1.2
[Sat Jun 10 04:18:58.303803 2017] [:error] [pid 11081] ipa: DEBUG: Cipher: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
[Sat Jun 10 04:18:58.336406 2017] [:error] [pid 11081] ipa: DEBUG: response status 200
[Sat Jun 10 04:18:58.336490 2017] [:error] [pid 11081] ipa: DEBUG: response headers {'date': 'Sat, 10 Jun 2017 02:18:58 GMT', 'content-length': '144', 'content-type': 'application/xml', 'server': 'Apache/2.4.6 (CentOS) mod_auth_gssapi/1.4.0 mod_nss/1.0.14 NSS/3.21 Basic ECC mod_wsgi/3.4 Python/2.7.5'}
[Sat Jun 10 04:18:58.336544 2017] [:error] [pid 11081] ipa: DEBUG: response body '<?xml version="1.0" encoding="UTF-8" standalone="no"?><XMLResponse><Status>1</Status><Error>String index out of range: -36</Error></XMLResponse>'
[Sat Jun 10 04:18:58.336951 2017] [:error] [pid 11081] ipa: DEBUG: parse_profile_submit_result_xml() xml_text:
[Sat Jun 10 04:18:58.336958 2017] [:error] [pid 11081] <?xml version="1.0" encoding="UTF-8" standalone="no"?><XMLResponse><Status>1</Status><Error>String index out of range: -36</Error></XMLResponse>
[Sat Jun 10 04:18:58.336960 2017] [:error] [pid 11081] parse_result:
[Sat Jun 10 04:18:58.336962 2017] [:error] [pid 11081] {'error_code': 1, 'error_string': u'String index out of range: -36'}
[Sat Jun 10 04:18:58.337049 2017] [:error] [pid 11081] ipa: ERROR: ra.request_certificate(): FAILURE (String index out of range: -36)
[Sat Jun 10 04:18:58.385983 2017] [:error] [pid 11081] ipa: DEBUG: WSGI wsgi_execute PublicError: Traceback (most recent call last):
[Sat Jun 10 04:18:58.386003 2017] [:error] [pid 11081]   File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 366, in wsgi_execute
[Sat Jun 10 04:18:58.386006 2017] [:error] [pid 11081]     result = command(*args, **options)
[Sat Jun 10 04:18:58.386008 2017] [:error] [pid 11081]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 449, in __call__
[Sat Jun 10 04:18:58.386009 2017] [:error] [pid 11081]     return self.__do_call(*args, **options)
[Sat Jun 10 04:18:58.386011 2017] [:error] [pid 11081]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 477, in __do_call
[Sat Jun 10 04:18:58.386012 2017] [:error] [pid 11081]     ret = self.run(*args, **options)
[Sat Jun 10 04:18:58.386014 2017] [:error] [pid 11081]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 799, in run
[Sat Jun 10 04:18:58.386015 2017] [:error] [pid 11081]     return self.execute(*args, **options)
[Sat Jun 10 04:18:58.386017 2017] [:error] [pid 11081]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/cert.py", line 629, in execute
[Sat Jun 10 04:18:58.386018 2017] [:error] [pid 11081]     csr, profile_id, ca_id, request_type=request_type)
[Sat Jun 10 04:18:58.386020 2017] [:error] [pid 11081]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 1612, in request_certificate
[Sat Jun 10 04:18:58.386022 2017] [:error] [pid 11081]     parse_result.get('error_string'))
[Sat Jun 10 04:18:58.386023 2017] [:error] [pid 11081]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 1334, in raise_certificate_operation_error
[Sat Jun 10 04:18:58.386025 2017] [:error] [pid 11081]     raise errors.CertificateOperationError(error=err_msg)
[Sat Jun 10 04:18:58.386026 2017] [:error] [pid 11081] CertificateOperationError: Certificate operation cannot be completed: FAILURE (String index out of range: -36)

And from /var/log/pki/pki-tomcat/ca/debug in think this is the relevant portion:

[10/Jun/2017:04:18:58][ajp-bio-127.0.0.1-8009-exec-9]: Finish parsePKCS10 - CN=vertica1.fakedomain.local
[10/Jun/2017:04:18:58][ajp-bio-127.0.0.1-8009-exec-9]: BasicProfile: populate() policy setid =serverCertSet
[10/Jun/2017:04:18:58][ajp-bio-127.0.0.1-8009-exec-9]: SubjectNameDefault: populate start
java.lang.StringIndexOutOfBoundsException: String index out of range: -36
        at java.lang.String.substring(String.java:1967)
        at com.netscape.certsrv.pattern.Pattern.substitute2(Pattern.java:128)
        at com.netscape.cms.profile.def.EnrollDefault.mapPattern(EnrollDefault.java:804)
        at com.netscape.cms.profile.def.SubjectNameDefault.populate(SubjectNameDefault.java:160)
        at com.netscape.cms.profile.def.EnrollDefault.populate(EnrollDefault.java:224)
        at com.netscape.cms.profile.common.BasicProfile.populate(BasicProfile.java:1101)
        at com.netscape.cms.profile.common.EnrollProfile.populate(EnrollProfile.java:1330)
        at com.netscape.cms.servlet.cert.CertProcessor.populateRequests(CertProcessor.java:362)
        at com.netscape.cms.servlet.cert.EnrollmentProcessor.processEnrollment(EnrollmentProcessor.java:181)
        at com.netscape.cms.servlet.cert.EnrollmentProcessor.processEnrollment(EnrollmentProcessor.java:96)
        at com.netscape.cms.servlet.profile.ProfileSubmitServlet.processEnrollment(ProfileSubmitServlet.java:243)
        at com.netscape.cms.servlet.profile.ProfileSubmitServlet.process(ProfileSubmitServlet.java:128)
        at com.netscape.cms.servlet.base.CMSServlet.service(CMSServlet.java:515)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        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:288)
        at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:285)
        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:320)
        at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:175)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:297)
        at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:55)
        at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:191)
        at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:187)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:186)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        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:288)
        at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:285)
        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:320)
        at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:260)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
        at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:55)
        at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:191)
        at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:187)
        at java.security.AccessController.doPrivileged(Native Method)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:186)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
        at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:190)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
        at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)
[10/Jun/2017:04:18:58][ajp-bio-127.0.0.1-8009-exec-9]: ProfileSubmitServlet: error in processing request: java.lang.StringIndexOutOfBoundsException: String index out of range: -36

So it looks to me like something is going wrong with SubjectNameDefault: but now, how do i fix this.

Hallo everybody,

I think i'm getting somewhere, but i need a little bit more help.

A couple of weeks ago the caIPAserviceCert.cfg was updated to fix a subject alternative names problem with the latest chrome browser. I've put back the original file from the RPM now and imported it with "ipa cerprofile-mod caIPAserviceCert --file=caIPAserviceCert.cfg". The error has now changed:

Number of certificates and requests being tracked: 1.
Request ID '20170610100215':
status: CA_UNREACHABLE
ca-error: Server at https://freeipa.fakedomain.local/ipa/xml failed request, will retry: 4301 (RPC failed at server.  Certificate operation cannot be completed: FAILURE (String index out of range: -1)).
stuck: no
key pair storage: type=FILE,location='/etc/pki/tls/private/vertica1.fakedomain.local.key'
certificate: type=FILE,location='/etc/pki/tls/certs/vertica1.fakedomain.local.crt'
CA: IPA
issuer: 
subject: 
expires: unknown
pre-save command: 
post-save command: 
track: yes
auto-renew: yes

And the relevant http error_log:

[Sat Jun 10 12:02:16.201423 2017] [:error] [pid 2589] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Sat Jun 10 12:02:16.201527 2017] [:error] [pid 2589] ipa: DEBUG: KerberosWSGIExecutioner.__call__:
[Sat Jun 10 12:02:16.218650 2017] [:error] [pid 2589] ipa: DEBUG: Created connection context.ldap2_140451304220432
[Sat Jun 10 12:02:16.218722 2017] [:error] [pid 2589] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Sat Jun 10 12:02:16.227438 2017] [:error] [pid 2589] ipa: DEBUG: raw: cert_request(u'<removed request for privacy reasons>', request_type=u'pkcs10', cacn=u'ipa', principal=<ipapython.kerberos.Principal object at 0x7fbd5fe6ac50>, add=True, all=False, raw
=False, version=u'2.51')
[Sat Jun 10 12:02:16.241057 2017] [:error] [pid 2589] ipa: DEBUG: raw: ca_is_enabled(version=u'2.213')
[Sat Jun 10 12:02:16.241180 2017] [:error] [pid 2589] ipa: DEBUG: ca_is_enabled(version=u'2.213')
[Sat Jun 10 12:02:16.242996 2017] [:error] [pid 2589] ipa: DEBUG: retrieving schema for SchemaCache url=ldapi://%2fvar%2frun%2fslapd-fakedomain-LOCAL.socket conn=<ldap.ldapobject.SimpleLDAPObject instance at 0x7
fbd5fe5ab90>
[Sat Jun 10 12:02:16.518140 2017] [:error] [pid 2589] ipa: DEBUG: raw: ca_show(u'ipa', version=u'2.213')
[Sat Jun 10 12:02:16.518322 2017] [:error] [pid 2589] ipa: DEBUG: ca_show(u'ipa', rights=False, all=False, raw=False, version=u'2.213')
[Sat Jun 10 12:02:16.518504 2017] [:error] [pid 2589] ipa: DEBUG: raw: ca_is_enabled(version=u'2.213')
[Sat Jun 10 12:02:16.518596 2017] [:error] [pid 2589] ipa: DEBUG: ca_is_enabled(version=u'2.213')
[Sat Jun 10 12:02:16.522149 2017] [:error] [pid 2589] ipa: DEBUG: IPA: virtual verify request certificate ignore caacl
[Sat Jun 10 12:02:16.526742 2017] [:error] [pid 2589] ipa: DEBUG: raw: host_show(u'vertica1.fakedomain.local', version=u'2.213')
[Sat Jun 10 12:02:16.527025 2017] [:error] [pid 2589] ipa: DEBUG: host_show(u'vertica1.fakedomain.local', rights=False, all=False, raw=False, version=u'2.213', no_members=False)
[Sat Jun 10 12:02:16.534007 2017] [:error] [pid 2589] ipa: DEBUG: raw: caacl_find(None, version=u'2.213', no_members=False)
[Sat Jun 10 12:02:16.534195 2017] [:error] [pid 2589] ipa: DEBUG: caacl_find(None, all=False, raw=False, version=u'2.213', no_members=False, pkey_only=False)
[Sat Jun 10 12:02:16.539724 2017] [:error] [pid 2589] ipa: DEBUG: raw: host_show(u'vertica1.fakedomain.local', all=True, version=u'2.213')
[Sat Jun 10 12:02:16.539910 2017] [:error] [pid 2589] ipa: DEBUG: host_show(u'vertica1.fakedomain.local', rights=False, all=True, raw=False, version=u'2.213', no_members=False)
[Sat Jun 10 12:02:16.556041 2017] [:error] [pid 2589] ipa: DEBUG: raw: host_show(u'vertica1.fakedomain.local', all=True, version=u'2.213')
[Sat Jun 10 12:02:16.556213 2017] [:error] [pid 2589] ipa: DEBUG: host_show(u'vertica1.fakedomain.local', rights=False, all=True, raw=False, version=u'2.213', no_members=False)
[Sat Jun 10 12:02:16.569401 2017] [:error] [pid 2589] ipa: DEBUG: raw: host_show(u'vertica1.fakedomain.local', version=u'2.213')
[Sat Jun 10 12:02:16.569574 2017] [:error] [pid 2589] ipa: DEBUG: host_show(u'vertica1.fakedomain.local', rights=False, all=False, raw=False, version=u'2.213', no_members=False)
[Sat Jun 10 12:02:16.576081 2017] [:error] [pid 2589] ipa: DEBUG: raw: caacl_find(None, version=u'2.213', no_members=False)
[Sat Jun 10 12:02:16.576277 2017] [:error] [pid 2589] ipa: DEBUG: caacl_find(None, all=False, raw=False, version=u'2.213', no_members=False, pkey_only=False)
[Sat Jun 10 12:02:16.579350 2017] [:error] [pid 2589] ipa: DEBUG: ra.request_certificate()
[Sat Jun 10 12:02:16.580814 2017] [:error] [pid 2589] ipa: DEBUG: request POST https://freeipa.fakedomain.local:443/ca/eeca/ca/profileSubmitSSLClient
[Sat Jun 10 12:02:16.580893 2017] [:error] [pid 2589] ipa: DEBUG: request body 'xml=true&profileId=caIPAserviceCert&authorityId=24c649da-1d89-40af-a1eb-72b776379eb0&cert_request=<removed for privacy reasons>%3D&cert_request_type=pkcs10'
[Sat Jun 10 12:02:16.580995 2017] [:error] [pid 2589] ipa: DEBUG: NSSConnection init freeipa.fakedomain.local
[Sat Jun 10 12:02:16.730493 2017] [:error] [pid 2589] ipa: DEBUG: Connecting: 192.168.0.10:0
[Sat Jun 10 12:02:16.741739 2017] [:error] [pid 2589] ipa: DEBUG: approved_usage = SSL Server intended_usage = SSL Server
[Sat Jun 10 12:02:16.741828 2017] [:error] [pid 2589] ipa: DEBUG: cert valid True for "CN=freeipa.fakedomain.local,O=fakedomain.LOCAL"
[Sat Jun 10 12:02:16.746383 2017] [:error] [pid 2589] ipa: DEBUG: handshake complete, peer = 192.168.0.10:443
[Sat Jun 10 12:02:16.746447 2017] [:error] [pid 2589] ipa: DEBUG: Protocol: TLS1.2
[Sat Jun 10 12:02:16.746493 2017] [:error] [pid 2589] ipa: DEBUG: Cipher: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
[Sat Jun 10 12:02:16.754408 2017] [:error] [pid 2589] ipa: DEBUG: approved_usage = SSL Server intended_usage = SSL Server
[Sat Jun 10 12:02:16.754489 2017] [:error] [pid 2589] ipa: DEBUG: cert valid True for "CN=freeipa.fakedomain.local,O=fakedomain.LOCAL"
[Sat Jun 10 12:02:16.766359 2017] [:error] [pid 2589] ipa: DEBUG: handshake complete, peer = 192.168.0.10:443
[Sat Jun 10 12:02:16.766423 2017] [:error] [pid 2589] ipa: DEBUG: Protocol: TLS1.2
[Sat Jun 10 12:02:16.766470 2017] [:error] [pid 2589] ipa: DEBUG: Cipher: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
[Sat Jun 10 12:02:16.860096 2017] [:error] [pid 2589] ipa: DEBUG: response status 200
[Sat Jun 10 12:02:16.860187 2017] [:error] [pid 2589] ipa: DEBUG: response headers {'date': 'Sat, 10 Jun 2017 10:02:16 GMT', 'content-length': '143', 'content-type': 'application/xml', 'server': 'Apache/2.4.6
(CentOS) mod_auth_gssapi/1.4.0 mod_nss/1.0.14 NSS/3.21 Basic ECC mod_wsgi/3.4 Python/2.7.5'}
[Sat Jun 10 12:02:16.860242 2017] [:error] [pid 2589] ipa: DEBUG: response body '<?xml version="1.0" encoding="UTF-8" standalone="no"?><XMLResponse><Status>1</Status><Error>String index out of range: -1</Erro
r></XMLResponse>'
[Sat Jun 10 12:02:16.860672 2017] [:error] [pid 2589] ipa: DEBUG: parse_profile_submit_result_xml() xml_text:
[Sat Jun 10 12:02:16.860679 2017] [:error] [pid 2589] <?xml version="1.0" encoding="UTF-8" standalone="no"?><XMLResponse><Status>1</Status><Error>String index out of range: -1</Error></XMLResponse>
[Sat Jun 10 12:02:16.860687 2017] [:error] [pid 2589] parse_result:
[Sat Jun 10 12:02:16.860689 2017] [:error] [pid 2589] {'error_code': 1, 'error_string': u'String index out of range: -1'}
[Sat Jun 10 12:02:16.860774 2017] [:error] [pid 2589] ipa: ERROR: ra.request_certificate(): FAILURE (String index out of range: -1)
[Sat Jun 10 12:02:16.915872 2017] [:error] [pid 2589] ipa: DEBUG: WSGI wsgi_execute PublicError: Traceback (most recent call last):
[Sat Jun 10 12:02:16.915906 2017] [:error] [pid 2589]   File "/usr/lib/python2.7/site-packages/ipaserver/rpcserver.py", line 366, in wsgi_execute
[Sat Jun 10 12:02:16.915912 2017] [:error] [pid 2589]     result = command(*args, **options)
[Sat Jun 10 12:02:16.915914 2017] [:error] [pid 2589]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 449, in __call__
[Sat Jun 10 12:02:16.915916 2017] [:error] [pid 2589]     return self.__do_call(*args, **options)
[Sat Jun 10 12:02:16.915918 2017] [:error] [pid 2589]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 477, in __do_call
[Sat Jun 10 12:02:16.915919 2017] [:error] [pid 2589]     ret = self.run(*args, **options)
[Sat Jun 10 12:02:16.915921 2017] [:error] [pid 2589]   File "/usr/lib/python2.7/site-packages/ipalib/frontend.py", line 799, in run
[Sat Jun 10 12:02:16.915923 2017] [:error] [pid 2589]     return self.execute(*args, **options)
[Sat Jun 10 12:02:16.915924 2017] [:error] [pid 2589]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/cert.py", line 629, in execute
[Sat Jun 10 12:02:16.915926 2017] [:error] [pid 2589]     csr, profile_id, ca_id, request_type=request_type)
[Sat Jun 10 12:02:16.915928 2017] [:error] [pid 2589]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 1612, in request_certificate
[Sat Jun 10 12:02:16.915929 2017] [:error] [pid 2589]     parse_result.get('error_string'))
[Sat Jun 10 12:02:16.915931 2017] [:error] [pid 2589]   File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py", line 1334, in raise_certificate_operation_error
[Sat Jun 10 12:02:16.915933 2017] [:error] [pid 2589]     raise errors.CertificateOperationError(error=err_msg)
[Sat Jun 10 12:02:16.915934 2017] [:error] [pid 2589] CertificateOperationError: Certificate operation cannot be completed: FAILURE (String index out of range: -1)
[Sat Jun 10 12:02:16.915936 2017] [:error] [pid 2589]
[Sat Jun 10 12:02:16.916120 2017] [:error] [pid 2589] ipa: INFO: [xmlserver] host/[e-mail]: cert_request(u'<removed for privacy reasons>', principal=u'host/[e-mail]', add=True, version=
u'2.51'): CertificateOperationError
[Sat Jun 10 12:02:16.916214 2017] [:error] [pid 2589] ipa: DEBUG: response: CertificateOperationError: Certificate operation cannot be completed: FAILURE (String index out of range: -1)
[Sat Jun 10 12:02:16.916801 2017] [:error] [pid 2589] ipa: DEBUG: no session id in request, generating empty session data with id=d4daa3c27378d6890f30deea15b65d7d
[Sat Jun 10 12:02:16.916920 2017] [:error] [pid 2589] ipa: DEBUG: store session: session_id=d4daa3c27378d6890f30deea15b65d7d start_timestamp=2017-06-10T12:02:16 access_timestamp=2017-06-10T12:02:16 expiration
_timestamp=1970-01-01T01:00:00
[Sat Jun 10 12:02:16.917574 2017] [:error] [pid 2589] ipa: DEBUG: finalize_kerberos_acquisition: xmlserver ccache_name="FILE:/var/run/httpd/ipa/clientcaches/host~[e-mail]-V0fnDF" s
ession_id="d4daa3c27378d6890f30deea15b65d7d"
[Sat Jun 10 12:02:16.917664 2017] [:error] [pid 2589] ipa: DEBUG: reading ccache data from file "/var/run/httpd/ipa/clientcaches/host~[e-mail]-V0fnDF"
[Sat Jun 10 12:02:16.918345 2017] [:error] [pid 2589] ipa: DEBUG: set_session_expiration_time: duration_type=inactivity_timeout duration=1200 max_age=1497175035.92 expiration=1497090136.92 (2017-06-10T12:22:1
6)
[Sat Jun 10 12:02:16.918427 2017] [:error] [pid 2589] ipa: DEBUG: store session: session_id=d4daa3c27378d6890f30deea15b65d7d start_timestamp=2017-06-10T12:02:16 access_timestamp=2017-06-10T12:02:16 expiration
_timestamp=2017-06-10T12:22:16
[Sat Jun 10 12:02:16.919817 2017] [:error] [pid 2589] ipa: DEBUG: Destroyed connection context.ldap2_140451304220432

And the tomcat debug log:

[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: according to ccMode, authorization for servlet: caProfileSubmitSSLClient is LDAP based, not XML {1}, use default authz mgr: {2}.
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: according to ccMode, authorization for servlet: caProfileSubmitSSLClient is LDAP based, not XML {1}, use default authz mgr: {2}.
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet:service() uri = /ca/eeca/ca/profileSubmitSSLClient
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet::service() param name='xml' value='true'
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet::service() param name='profileId' value='caIPAserviceCert'
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet::service() param name='authorityId' value='24c649da-1d89-40af-a1eb-72b776379eb0'
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet::service() param name='cert_request' value='(sensitive)'
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet::service() param name='cert_request_type' value='pkcs10'
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: caProfileSubmitSSLClient start to service.
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: xmlOutput true
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: ProfileSubmitServlet: isRenewal false
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: according to ccMode, authorization for servlet: caProfileSubmit is LDAP based, not XML {1}, use default authz mgr: {2}.
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: ProfileSubmitServlet: profile: caIPAserviceCert
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CAProcessor: Input Parameters:
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CAProcessor: - isRenewal: false
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CAProcessor: - remoteHost: 192.168.0.10
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CAProcessor: - cert_request_type: pkcs10
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CAProcessor: - profileId: caIPAserviceCert
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CAProcessor: - cert_request: (sensitive)
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CAProcessor: - remoteAddr: 192.168.0.10
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollmentProcessor: isRenewal false
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollmentProcessor: profileId caIPAserviceCert
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollmentProcessor: set Inputs into profile Context
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollmentProcessor: authenticator raCertAuth found
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CertProcessor: No authenticator credentials required
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollmentProcessor: set sslClientCertProvider
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: authenticate: authentication required.
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: in auditSubjectID
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: auditSubjectID auditContext {sslClientCertProvider=com.netscape.cms.servlet.profile.SSLClientCertProvider@723e403b, profileContext=com.netsca
pe.cms.profile.common.ProfileContext@7b3d33dd}
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet auditSubjectID: subjectID: null
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: AgentCertAuthentication: start
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: authenticator instance name is raCertAuth
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: AgentCertAuthenticator: got provider
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: AgentCertAuthenticator: retrieving client certificate
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: AgentCertAuthenticator: got certificates
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFactory::getConn()
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connected: true
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is connected true
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns now 4
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConns now 5
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFactory::getConn()
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connected: true
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is connected true
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns now 2
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConns now 3
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: check if ipara is  in group Registration Manager Agents
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: UGSubsystem.isMemberOf() using new lookup code
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFactory::getConn()
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connected: true
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is connected true
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns now 2
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: authorization search base: cn=Registration Manager Agents,ou=groups,o=ipaca
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: authorization search filter: (uniquemember=uid=ipara,ou=people,o=ipaca)
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: authorization result: true
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConns now 3
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: AgentCertAuthentication: authenticated uid=ipara,ou=people,o=ipaca
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: SignedAuditEventFactory: create() message created for eventType=AUTH_SUCCESS

[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CertProcessor authToken not null
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CAProcessor: authz using acl:
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Start parsePKCS10(): <removed for privacy reasons>
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollProfile: parsePKCS10: signature verification enabled
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollProfile: parsePKCS10: use internal token
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollProfile: parsePKCS10 setting thread token
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollProfile: parsePKCS10 restoring thread token
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Repository: in getNextSerialNumber.
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFactory::getConn()
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connected: true
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is connected true
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns now 4
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Repository: getSerialNumber()
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConns now 5
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Repository: getSerialNumber  serial=0
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Repository: in InitCache
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Repository: Instance of Request Repository or CRLRepository.
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Repository: minSerial:1 maxSerial: 10000000
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Repository: nextMinSerial:  nextMaxSerial:
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Repository: increment:10000000 lowWaterMark: 2000000
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: RequestRepository: in getLastSerialNumberInRange: min 1 max 10000000
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: RequestRepository: mRequestQueue com.netscape.cmscore.request.RequestQueue@50d3b8c5
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: RequestRepository: about to call mRequestQueue.getLastRequestIdInRange
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: RequestQueue: getLastRequestId: low 1 high 10000000
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: RequestQueue: getLastRequestId: filter (requeststate=*) fromId 10000000
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: In LdapBoundConnFactory::getConn()
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: masterConn is connected: true
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: getConn: conn is connected true
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: getConn: mNumConns now 4
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: In DBVirtualList filter attrs startFrom sortKey pageSize filter: (requeststate=*) attrs: null pageSize -5 startFrom 0810000000
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: returnConn: mNumConns now 5
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: searching for entry 0810000000
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList.getEntries()
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: entries: 6
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: top: 64
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: DBVirtualList: size: 70
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: RequestQueue: getLastRequestId: size   70
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: RequestQueue: getSizeBeforeJumpTo: 70
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: RequestQueue: curReqId: 70
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: RequestQueue: getLastRequestId : returning value 70
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Repository:  mLastSerialNo: 70
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Repository: checkRange  mLastSerialNo=71
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Repository: getNextSerialNumber: returning retSerial 71
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollProfile: setDefaultCertInfo: setting issuerDN using exact CA signing cert subjectDN encoding
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollProfile: createRequest 71
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CertProcessor: request from RA: ipara
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CertProcessor: profileSetid=serverCertSet
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CertProcessor: request 71
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CertProcessor: populating request inputs
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Start parsePKCS10(): <removed for privacy reasons>
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollProfile: parsePKCS10: signature verification enabled
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollProfile: parsePKCS10: use internal token
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollProfile: parsePKCS10 setting thread token
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: EnrollProfile: parsePKCS10 restoring thread token
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Found PKCS10 extension
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Set extensions [ObjectId: 2.5.29.17 Criticality=false
SubjectAlternativeName [
[DNSName: vertica1.fakedomain.local, OtherName: (UTF8String)1.3.6.1.4.1.311.20.2.3,host/[e-mail], OtherName: (Any)1.3.6.1.5.2.2,303ca00f1b0d43524f5353594e2e4c4f43414ca1293027a00302010
1a120301e1b04686f73741b1676657274696361312e63726f7373796e2e6c6f63616c]]
, oid=2.5.29.37  val=48 10 6 8 43 6 1 5 5 7 3 1 , ObjectId: 2.5.29.19 Criticality=true
BasicConstraints:[
CA:false
PathLen: undefined
]
, ObjectId: 2.5.29.14 Criticality=false
SubjectKeyIdentifier [
KeyIdentifier [
09 93 FD D2 46 C6 38 0B 20 A1 60 2C BC 65 0D FF C1 3E 78 84
]
]
]
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: Finish parsePKCS10 - CN=vertica1.fakedomain.local
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: BasicProfile: populate() policy setid =serverCertSet
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: SubjectNameDefault: populate start
java.lang.StringIndexOutOfBoundsException: String index out of range: -1
at java.lang.String.substring(String.java:1967)
at com.netscape.certsrv.pattern.Pattern.substitute2(Pattern.java:132)
at com.netscape.cms.profile.def.EnrollDefault.mapPattern(EnrollDefault.java:804)
at com.netscape.cms.profile.def.SubjectNameDefault.populate(SubjectNameDefault.java:160)
at com.netscape.cms.profile.def.EnrollDefault.populate(EnrollDefault.java:224)
at com.netscape.cms.profile.common.BasicProfile.populate(BasicProfile.java:1101)
at com.netscape.cms.profile.common.EnrollProfile.populate(EnrollProfile.java:1330)
at com.netscape.cms.servlet.cert.CertProcessor.populateRequests(CertProcessor.java:362)
at com.netscape.cms.servlet.cert.EnrollmentProcessor.processEnrollment(EnrollmentProcessor.java:181)
at com.netscape.cms.servlet.cert.EnrollmentProcessor.processEnrollment(EnrollmentProcessor.java:96)
at com.netscape.cms.servlet.profile.ProfileSubmitServlet.processEnrollment(ProfileSubmitServlet.java:243)
at com.netscape.cms.servlet.profile.ProfileSubmitServlet.process(ProfileSubmitServlet.java:128)
at com.netscape.cms.servlet.base.CMSServlet.service(CMSServlet.java:515)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:499)
at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:288)
at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:285)
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:320)
at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:175)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:297)
at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:55)
at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:191)
at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:187)
at java.security.AccessController.doPrivileged(Native Method)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:186)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
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:288)
at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:285)
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:320)
at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:260)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
at org.apache.catalina.core.ApplicationFilterChain.access$000(ApplicationFilterChain.java:55)
at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:191)
at org.apache.catalina.core.ApplicationFilterChain$1.run(ApplicationFilterChain.java:187)
at java.security.AccessController.doPrivileged(Native Method)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:186)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:436)
at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:190)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)
at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: ProfileSubmitServlet: error in processing request: java.lang.StringIndexOutOfBoundsException: String index out of range: -1
[10/Jun/2017:12:02:16][ajp-bio-127.0.0.1-8009-exec-1]: CMSServlet: curDate=Sat Jun 10 12:02:16 CEST 2017 id=caProfileSubmitSSLClient time=78

Any ideas?

Best regards,

Jochem Kuijpers

Hello everybody,

Still need some help. I'm a bit further already. I'm pretty sure the error is in the caIPAserviceCert profile. Would someone please take a look? The whole profile is below.

I suspect something is wrong in this section:

policyset.serverCertSet.1.default.class_id=subjectNameDefaultImpl
policyset.serverCertSet.1.default.name=Subject Name Default
policyset.serverCertSet.1.default.params.name=CN=$$request.req_subject_name.cn$$, $SUBJECT_DN_O

but i can not figure out what is wrong. When i change the double $$ in the last line to single $ signes i get the String in index out of range -36, when i leave the double $$ in i get the string index out of range -36.

Please help.

auth.instance_id=raCertAuth
classId=caEnrollImpl
desc=This certificate profile is for enrolling server certificates with IPA-RA agent authentication.
enable=true
enableBy=ipara
input.i1.class_id=certReqInputImpl
input.i2.class_id=submitterInfoInputImpl
input.list=i1,i2
name=IPA-RA Agent-Authenticated Server Certificate Enrollment
output.list=o1
output.o1.class_id=certOutputImpl
policyset.list=serverCertSet
policyset.serverCertSet.1.constraint.class_id=subjectNameConstraintImpl
policyset.serverCertSet.1.constraint.name=Subject Name Constraint
policyset.serverCertSet.1.constraint.params.accept=true
policyset.serverCertSet.1.constraint.params.pattern=CN=[^,]+,.+
policyset.serverCertSet.1.default.class_id=subjectNameDefaultImpl
policyset.serverCertSet.1.default.name=Subject Name Default
policyset.serverCertSet.1.default.params.name=CN=$$request.req_subject_name.cn$$, $SUBJECT_DN_O
policyset.serverCertSet.10.constraint.class_id=noConstraintImpl
policyset.serverCertSet.10.constraint.name=No Constraint
policyset.serverCertSet.10.default.class_id=subjectKeyIdentifierExtDefaultImpl
policyset.serverCertSet.10.default.name=Subject Key Identifier Extension Default
policyset.serverCertSet.10.default.params.critical=false
policyset.serverCertSet.11.constraint.class_id=noConstraintImpl
policyset.serverCertSet.11.constraint.name=No Constraint
policyset.serverCertSet.11.default.class_id=userExtensionDefaultImpl
policyset.serverCertSet.11.default.name=User Supplied Extension Default
policyset.serverCertSet.11.default.params.userExtOID=2.5.29.17
policyset.serverCertSet.2.constraint.class_id=validityConstraintImpl
policyset.serverCertSet.2.constraint.name=Validity Constraint
policyset.serverCertSet.2.constraint.params.notAfterCheck=false
policyset.serverCertSet.2.constraint.params.notBeforeCheck=false
policyset.serverCertSet.2.constraint.params.range=740
policyset.serverCertSet.2.default.class_id=validityDefaultImpl
policyset.serverCertSet.2.default.name=Validity Default
policyset.serverCertSet.2.default.params.range=731
policyset.serverCertSet.2.default.params.startTime=0
policyset.serverCertSet.3.constraint.class_id=keyConstraintImpl
policyset.serverCertSet.3.constraint.name=Key Constraint
policyset.serverCertSet.3.constraint.params.keyParameters=1024,2048,3072,4096
policyset.serverCertSet.3.constraint.params.keyType=RSA
policyset.serverCertSet.3.default.class_id=userKeyDefaultImpl
policyset.serverCertSet.3.default.name=Key Default
policyset.serverCertSet.4.constraint.class_id=noConstraintImpl
policyset.serverCertSet.4.constraint.name=No Constraint
policyset.serverCertSet.4.default.class_id=authorityKeyIdentifierExtDefaultImpl
policyset.serverCertSet.4.default.name=Authority Key Identifier Default
policyset.serverCertSet.5.constraint.class_id=noConstraintImpl
policyset.serverCertSet.5.constraint.name=No Constraint
policyset.serverCertSet.5.default.class_id=authInfoAccessExtDefaultImpl
policyset.serverCertSet.5.default.name=AIA Extension Default
policyset.serverCertSet.5.default.params.authInfoAccessADEnable_0=true
policyset.serverCertSet.5.default.params.authInfoAccessADLocationType_0=URIName
policyset.serverCertSet.5.default.params.authInfoAccessADLocation_0=http://$IPA_CA_RECORD.$DOMAIN/ca/ocsp
policyset.serverCertSet.5.default.params.authInfoAccessADMethod_0=1.3.6.1.5.5.7.48.1
policyset.serverCertSet.5.default.params.authInfoAccessCritical=false
policyset.serverCertSet.5.default.params.authInfoAccessNumADs=1
policyset.serverCertSet.6.constraint.class_id=keyUsageExtConstraintImpl
policyset.serverCertSet.6.constraint.name=Key Usage Extension Constraint
policyset.serverCertSet.6.constraint.params.keyUsageCritical=true
policyset.serverCertSet.6.constraint.params.keyUsageCrlSign=false
policyset.serverCertSet.6.constraint.params.keyUsageDataEncipherment=true
policyset.serverCertSet.6.constraint.params.keyUsageDecipherOnly=false
policyset.serverCertSet.6.constraint.params.keyUsageDigitalSignature=true
policyset.serverCertSet.6.constraint.params.keyUsageEncipherOnly=false
policyset.serverCertSet.6.constraint.params.keyUsageKeyAgreement=false
policyset.serverCertSet.6.constraint.params.keyUsageKeyCertSign=false
policyset.serverCertSet.6.constraint.params.keyUsageKeyEncipherment=true
policyset.serverCertSet.6.constraint.params.keyUsageNonRepudiation=true
policyset.serverCertSet.6.default.class_id=keyUsageExtDefaultImpl
policyset.serverCertSet.6.default.name=Key Usage Default
policyset.serverCertSet.6.default.params.keyUsageCritical=true
policyset.serverCertSet.6.default.params.keyUsageCrlSign=false
policyset.serverCertSet.6.default.params.keyUsageDataEncipherment=true
policyset.serverCertSet.6.default.params.keyUsageDecipherOnly=false
policyset.serverCertSet.6.default.params.keyUsageDigitalSignature=true
policyset.serverCertSet.6.default.params.keyUsageEncipherOnly=false
policyset.serverCertSet.6.default.params.keyUsageKeyAgreement=false
policyset.serverCertSet.6.default.params.keyUsageKeyCertSign=false
policyset.serverCertSet.6.default.params.keyUsageKeyEncipherment=true
policyset.serverCertSet.6.default.params.keyUsageNonRepudiation=true
policyset.serverCertSet.7.constraint.class_id=noConstraintImpl
policyset.serverCertSet.7.constraint.name=No Constraint
policyset.serverCertSet.7.default.class_id=extendedKeyUsageExtDefaultImpl
policyset.serverCertSet.7.default.name=Extended Key Usage Extension Default
policyset.serverCertSet.7.default.params.exKeyUsageCritical=false
policyset.serverCertSet.7.default.params.exKeyUsageOIDs=1.3.6.1.5.5.7.3.1,1.3.6.1.5.5.7.3.2
policyset.serverCertSet.8.constraint.class_id=signingAlgConstraintImpl
policyset.serverCertSet.8.constraint.name=No Constraint
policyset.serverCertSet.8.constraint.params.signingAlgsAllowed=SHA1withRSA,SHA256withRSA,SHA512withRSA,MD5withRSA,MD2withRSA,SHA1withDSA,SHA1withEC,SHA256withEC,SHA384withEC,SHA512withEC
policyset.serverCertSet.8.default.class_id=signingAlgDefaultImpl
policyset.serverCertSet.8.default.name=Signing Alg
policyset.serverCertSet.8.default.params.signingAlg=-
policyset.serverCertSet.9.constraint.class_id=noConstraintImpl
policyset.serverCertSet.9.constraint.name=No Constraint
policyset.serverCertSet.9.default.class_id=crlDistributionPointsExtDefaultImpl
policyset.serverCertSet.9.default.name=CRL Distribution Points Extension Default
policyset.serverCertSet.9.default.params.crlDistPointsCritical=false
policyset.serverCertSet.9.default.params.crlDistPointsEnable_0=true
policyset.serverCertSet.9.default.params.crlDistPointsIssuerName_0=$CRL_ISSUER
policyset.serverCertSet.9.default.params.crlDistPointsIssuerType_0=DirectoryName
policyset.serverCertSet.9.default.params.crlDistPointsNum=1
policyset.serverCertSet.9.default.params.crlDistPointsPointName_0=http://$IPA_CA_RECORD.$DOMAIN/ipa/crl/MasterCRL.bin
policyset.serverCertSet.9.default.params.crlDistPointsPointType_0=URIName
policyset.serverCertSet.9.default.params.crlDistPointsReasons_0=
policyset.serverCertSet.list=1,2,3,4,5,6,7,8,9,10,11
profileId=caIPAserviceCert
visible=false

Best regards,

Jochem Kuijpers

Hello all,

I finally got something working, and found something of a cause.

I replaced 
policyset.serverCertSet.1.default.params.name=CN=$$request.req_subject_name.cn$$, $SUBJECT_DN_O
with
policyset.serverCertSet.1.default.params.name=CN=$request.req_subject_name.cn$, o=FAKEDOMAIN.LOCAL

imported the new profile, the error was gone and the certificate issued.

Some further investigation showed me it wasn't just right yet. I examed the certificate and found this (removed the other parts of the certificate:

Authority Information Access: 
                OCSP - URI:http://$IPA_CA_RECORD.$DOMAIN/ca/ocsp

Full Name:
                  URI:http://$IPA_CA_RECORD.$DOMAIN/ipa/crl/MasterCRL.bin

So somehow the variables are not being processed. For now i just put the domain name in the profile and it is working.

Does anyone have any idea why this is (not) happening? And how to fix it? For now it is working but i would like the original profile working again.

Best regards,

Jochem Kuijpers

[Fraser Tweedale]

On Sun, Jun 11, 2017 at 12:46:31AM -0000, jochem--- via FreeIPA-users wrote:
> Hello all,
>
> I finally got something working, and found something of a cause.
>
> I replaced 
> policyset.serverCertSet.1.default.params.name=CN=$$request.req_subject_name.cn$$, $SUBJECT_DN_O
> with
> policyset.serverCertSet.1.default.params.name=CN=$request.req_subject_name.cn$, o=FAKEDOMAIN.LOCAL
>
> imported the new profile, the error was gone and the certificate issued.
>
> Some further investigation showed me it wasn't just right yet. I examed the certificate and found this (removed the other parts of the certificate:
>         Authority Information Access: 
>             OCSP - URI:http://$IPA_CA_RECORD.$DOMAIN/ca/ocsp
>
>             Full Name:
>               URI:http://$IPA_CA_RECORD.$DOMAIN/ipa/crl/MasterCRL.bin
>
> So somehow the variables are not being processed. For now i just put the domain name in the profile and it is working.
>
> Does anyone have any idea why this is (not) happening? And how to fix it? For now it is working but i would like the original profile working again.
>
> Best regards,
>
> Jochem Kuijpers

You are very close to hitting on the solution.

It looks like you have taken the profile configuration directly from
/usr/share/ipa/profiles/.  These are not ready-to-go profiles;
rather they are profile TEMPLATES containing variable substitutions
for FreeIPA to perform, before the profile gets loaded into Dogtag.

The '$$' is for a literal '$', and the '$IPA_CA_RECORD', '$DOMAIN',
'$SUBJECT_DN_O' and so on, are the variable substitutions that IPA
performs.  So from here, you should perform those substitutions
yourself, including the '$$' -> '$'.

When you modify a profile it is recommended to use `ipa
certprofile-show --out FILENAME` to export the current profile
configuration from Dogtag, then edit that and update the profile via
`ipa certprofile-mod`.

HTH,
Fraser