8:03 p.m.
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
9:11 p.m.
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 -- freeipa-users(a)lists.fedorahosted.org
To unsubscribe send an email to freeipa-users-leave(a)lists.fedorahosted.org
9:34 p.m.
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.
5:23 a.m.
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/vertica1.fakedomain.local(a)fakedomain.LOCAL: cert_request(u'<removed for
privacy reasons>',
principal=u'host/vertica1.fakedomain.local(a)fakedomain.LOCAL', 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~vertica1.fakedomain.local@fakedomain.LOCAL-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~vertica1.fakedomain.local(a)fakedomain.LOCAL-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/vertica1.fakedomain.local(a)fakedomain.LOCAL,
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
12:55 p.m.
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
7:46 p.m.
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
9:29 p.m.
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
2509
days inactive
2511
days old
freeipa-users@lists.fedorahosted.org
6 comments
3 participants
participants (3)
-
Fraser Tweedale -
jochem＠kuijpersadvies.nl -
Rob Crittenden