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