Bug 1585945

Summary:	CMC CRMF requests result in InvalidKeyFormatException when signing algorithm is ECC [rhel-7.5.z]
Product:	Red Hat Enterprise Linux 7	Reporter:	Oneata Mircea Teodor <toneata>
Component:	pki-core	Assignee:	Christina Fu <cfu>
Status:	CLOSED ERRATA	QA Contact:	Asha Akkiangady <aakkiang>
Severity:	high	Docs Contact:	Marc Muehlfeld <mmuehlfe>
Priority:	high
Version:	7.5	CC:	cfu, gkapoor, mharmsen, msauton, ssidhaye
Target Milestone:	rc	Keywords:	TestCaseProvided, ZStream
Target Release:	---
Hardware:	All
OS:	Linux
Whiteboard:
Fixed In Version:	pki-core-10.5.1-13.1.el7_5	Doc Type:	Bug Fix
Doc Text:	Previously, during verification, Certificate System encoded the ECC public key incorrectly in CMC Certificate Request Message Format (CRMF) requests. As a consequence, requesting an ECC certificate with Certificate Management over CMS (CMC) in CRMF failed. The problem has been fixed, and as a result, CMC CRMF requests using ECC keys work as expected.	Story Points:	---
Clone Of:	1580394	Environment:
Last Closed:	2018-06-26 16:47:59 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:	1580394
Bug Blocks:

Description Oneata Mircea Teodor 2018-06-05 07:18:26 UTC

This bug has been copied from bug #1580394 and has been proposed to be backported to 7.5 z-stream (EUS).

Comment 2 Christina Fu 2018-06-05 17:12:29 UTC

commit d7eca28b1d72804e1cfabeb6851aa393fafe39c7 (HEAD -> DOGTAG_10_5_BRANCH, origin/DOGTAG_10_5_BRANCH)
Author: Christina Fu <cfu>
Date:   Mon Jun 4 11:03:20 2018 -0700

    Ticket 3028 additional error checking
    
    Change-Id: If660fabd21b9992416dd1d5463b6ffd68fa1bf43

commit f8da5db790777ab4c0bd8ab08c5d4932e2f25349
Author: Christina Fu <cfu>
Date:   Mon Jun 4 10:53:12 2018 -0700

    Ticket 3028 CMC CRMF request results in InvalidKeyFormatException when signing algorithm is ECC
    
    This patch fixes the issue where in case of CRMF request with ECC keys the
    public key was encoded incorrectly previously.
    
    The fix was done in a way that RSA portion is unaffected.
    
    Fixes https://pagure.io/dogtagpki/issue/3028
    
    Change-Id: I3eb62638f2970dc7a9df37abb19015bd287b383d

Comment 3 Christina Fu 2018-06-05 17:27:31 UTC

Test procedure:
As reported in the original bug: https://bugzilla.redhat.com/show_bug.cgi?id=1580394#c0
Just generate a selfsign ECC CRMF CMC request and submit as a non-agent user, using any of the non-agent CMC profile.
Observe that it should succeed.

Comment 9 Christina Fu 2018-06-14 16:49:49 UTC

Geetika could you please help him by first reviewing his test case detail, and then help him to resolve issues until the test result appears to be more meaningful, either successful or not? Thank you.

Comment 10 Christina Fu 2018-06-14 17:26:48 UTC

(In reply to Christina Fu from comment #9)
> Geetika could you please help him by first reviewing his test case detail,
> and then help him to resolve issues until the test result appears to be more
> meaningful, either successful or not? Thank you.

Just to clarify.  Some minimal effort of debugging from QE is much appreciated.  Take this bug for example, you can see that your CA has issue talking to your KRA.  Then ask yourself, does that have anything to do with the nature of this bug?  You would want to try to resolve this unrelated issue (ask for help from your team mate if you aren't sure) so you can either successfully verify the bug, or get closer to the heart of the issue if there really is problem with the fix.
thanks.

Comment 11 Geetika Kapoor 2018-06-15 09:42:16 UTC

Sure, I'll look into this.Finishing few bugzilla's assigned on my name and then will work with sumedh on this.

Comment 12 Geetika Kapoor 2018-06-15 16:00:12 UTC

Test Env:
========

# rpm -qa pki-* jss* nss*
pki-symkey-10.5.1-13.1.el7_5.x86_64
pki-server-10.5.1-13.1.el7_5.noarch
pki-tks-10.5.1-12.el7pki.noarch
pki-console-10.5.1-5.el7pki.noarch
pki-usgov-dod-cacerts-0.0.6-4.el7.noarch
pki-ca-10.5.1-13.1.el7_5.noarch
pki-kra-10.5.1-13.1.el7_5.noarch
pki-base-10.5.1-13.1.el7_5.noarch
pki-tools-10.5.1-13.1.el7_5.x86_64
jss-4.4.0-12.el7_5.x86_64
pki-base-java-10.5.1-13.1.el7_5.noarch
pki-tps-10.5.1-12.el7pki.x86_64
pki-javadoc-10.5.1-13.1.el7_5.noarch
pki-core-debuginfo-10.5.1-13.1.el7_5.x86_64
pki-ocsp-10.5.1-12.el7pki.noarch

Test Cases:
==========

Test Case 1: Run CMC/Http with CRMFPopClient with -a and request.selfSign=true
===============================================================================

1.Run crmfpopclient.

# CRMFPopClient -d subca-db/ -p SECret.123 -n UID=testuser100 -b transport.pem  -a ec -t false -y  -w "AES/CBC/PKCS5Padding" -o crmf2.req
Keypair private key id: 5150274d0e01d4f42bdd8f8865edb4046148967a
CRMFPopClient: self_sign true. Generating SubjectKeyIdentifier extension.
CryptoUtil: createKeyIdentifier: begins
Storing CRMF requrest into crmf2.req


2. Now run cmc request file after setting correct private id in 

3. Now run HttpClient with profile == caECFullCMCSelfSignedCert

4. Now send Http Request.

11. Make sure cert is generated and is archived.

verification 1: Check logs for both KRA and CA
-------------

debug logs CA:


[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SignedAuditLogger: event ACCESS_SESSION_ESTABLISH
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet:service() uri = /ca/ee/ca/profileSubmitCMCFull
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet::service() param name='profileId' value='caECFullCMCSelfSignedCert'
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet: caProfileSubmitCMCFull start to service.
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: Start of ProfileSubmitCMCServlet Input Parameters
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet Input Parameter profileId='caECFullCMCSelfSignedCert'
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: End of ProfileSubmitCMCServlet Input Parameters
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: start serving
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: SubId=profile
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: profileId caECFullCMCSelfSignedCert
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: authenticator CMCUserSignedAuth found
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: set Inputs into Context
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: set sslClientCertProvider
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet: in auditSubjectID
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet: auditSubjectID auditContext {sslClientCertProvider=com.netscape.cms.servlet.profile.SSLClientCertProvider@73fbf03e, profileContext=com.netscape.cms.profile.common.ProfileContext@36f96025}
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet auditSubjectID: subjectID: null
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: authenticate: begins
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth:createAuditSubjectFromCert:  Principal name = UID=test10,CN=test10,O=example.org
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: authenticate: cmc request content is signed data
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: verifySignerInfo: begins
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: verifySignerInfo: SignerIdentifier type: SUBJECT_KEY_IDENTIFIER
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: verifySignerInfo: selfSigned is true
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: authenticate:  self-signed cmc request will not have user identification info at this point.
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: authenticate: numReqs not 0, assume enrollment request
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: authenticate:  type is CRMF
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: authenticate: setting requestCertSubject to: 
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: authenticate: SubjectKeyIdentifierExtension found
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: authenticate: signing key alg=EC
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: authenticate: got X509Key 
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: authenticate: public key retrieved
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: verifySelfSignedCMC: begins
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: verifySelfSignedCMC:  SignerIdentifier SUBJECT_KEY_IDENTIFIER matches SKI of request
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: verifySelfSignedCMC: verifying request signature with public key
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: verifySelfSignedCMC:  signature verified
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SignedAuditLogger: event CMC_USER_SIGNED_REQUEST_SIG_VERIFY
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCUserSignedAuth: authenticate: ends successfully; returning authToken
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: authenticate: setting auditSubjectID in SessionContext:$Unidentified$
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet authToken not null
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet.authorize(DirAclAuthz)
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet: in auditSubjectID
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet: auditSubjectID auditContext {sslClientCertProvider=com.netscape.cms.servlet.profile.SSLClientCertProvider@73fbf03e, cmcRequestCertSubject=<null>, userid=$Unidentified$, profileContext=com.netscape.cms.profile.common.ProfileContext@36f96025, sslClientCert=[
[
  Version: V3
  Subject: UID=test10,CN=test10,O=example.org
  Signature Algorithm: SHA384withEC, OID = 1.2.840.10045.4.3.3

  Key:  algorithm = RSA, unparsed keybits = 
30 81 89 02 81 81 00 C0 97 5B 81 DD 9C D9 5C A0 D1 F4 F0 9A 
CF 7D C7 E1 C5 A4 3F A6 2E 0B 77 27 54 71 0D 2A AC 62 9B 46 
E6 89 24 09 63 34 DE 5A 86 00 C2 DD 64 06 66 63 17 04 2A EC 
A8 19 46 1E 1A 5D B5 15 26 4C 3A 6A 00 64 85 62 EA A2 38 3F 
2D C0 CF 87 44 4B 01 22 6B 42 9A 02 7F AA 70 5F 94 36 CE 04 
5C AB D6 A8 32 22 7D 4A AC 22 D3 9C CF CB 61 18 08 C3 73 14 
B9 37 21 07 63 B0 54 CA 98 F2 FA BA 35 67 65 02 03 01 00 01

  Validity: [From: Fri Jun 15 10:48:45 EDT 2018,
               To: Wed Dec 12 10:48:45 EST 2018]
  Issuer: CN=Company Root CA2,O=Company,C=US
  SerialNumber: [    0f]
  Extension[0] = ObjectId: 2.5.29.35 Criticality=false
AuthorityKeyIdentifier [
KeyIdentifier [
74 10 CB CF 97 7A 7C 66 95 E4 AF 92 10 34 F0 25 07 56 B2 16
]
]
  Extension[1] = ObjectId: 1.3.6.1.5.5.7.1.1 Criticality=false
AuthInfoAccess [
(0) 1.3.6.1.5.5.7.48.1 URIName: http://nocp4.idm.lab.eng.rdu2.redhat.com:28080/ca/ocsp]
  Extension[2] = ObjectId: 2.5.29.15 Criticality=true
KeyUsage [
  DigitalSignature
  Non_repudiation
  Key_Encipherment
]
  Extension[3] = oid=2.5.29.37  val=48 20 6 8 43 6 1 5 5 7 3 2 6 8 43 6 1 5 5 7 3 4 
]
  Algorithm: [SHA384withEC]
  Signature:
30 64 02 30 04 DD BF 58 36 12 61 AD 26 C2 03 0B AB BF 67 33 
ED 22 E7 8A 0F 3D 1D F6 03 89 D7 83 22 83 F1 95 C9 12 D5 8A 
4B ED 08 45 7C 05 AE DF 6B 46 EC 4E 02 30 12 F9 2B 61 CD 7A 
8B 0B D1 CC 6A C1 87 19 0E 85 E6 64 BE 86 41 CF 4A D5 61 02 
0C B4 FA DE 0E 4E 3B 1D FA 38 D8 55 EF 3A C1 A0 E8 9C 64 90 
B8 C4
], authManagerId=CMCUserSignedAuth}
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet auditSubjectID: subjectID: $Unidentified$
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet: in auditGroupID
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet: auditGroupID auditContext {sslClientCertProvider=com.netscape.cms.servlet.profile.SSLClientCertProvider@73fbf03e, cmcRequestCertSubject=<null>, userid=$Unidentified$, profileContext=com.netscape.cms.profile.common.ProfileContext@36f96025, sslClientCert=[
[
  Version: V3
  Subject: UID=test10,CN=test10,O=example.org
  Signature Algorithm: SHA384withEC, OID = 1.2.840.10045.4.3.3

  Key:  algorithm = RSA, unparsed keybits = 
30 81 89 02 81 81 00 C0 97 5B 81 DD 9C D9 5C A0 D1 F4 F0 9A 
CF 7D C7 E1 C5 A4 3F A6 2E 0B 77 27 54 71 0D 2A AC 62 9B 46 
E6 89 24 09 63 34 DE 5A 86 00 C2 DD 64 06 66 63 17 04 2A EC 
A8 19 46 1E 1A 5D B5 15 26 4C 3A 6A 00 64 85 62 EA A2 38 3F 
2D C0 CF 87 44 4B 01 22 6B 42 9A 02 7F AA 70 5F 94 36 CE 04 
5C AB D6 A8 32 22 7D 4A AC 22 D3 9C CF CB 61 18 08 C3 73 14 
B9 37 21 07 63 B0 54 CA 98 F2 FA BA 35 67 65 02 03 01 00 01

  Validity: [From: Fri Jun 15 10:48:45 EDT 2018,
               To: Wed Dec 12 10:48:45 EST 2018]
  Issuer: CN=Company Root CA2,O=Company,C=US
  SerialNumber: [    0f]
  Extension[0] = ObjectId: 2.5.29.35 Criticality=false
AuthorityKeyIdentifier [
KeyIdentifier [
74 10 CB CF 97 7A 7C 66 95 E4 AF 92 10 34 F0 25 07 56 B2 16
]
]
  Extension[1] = ObjectId: 1.3.6.1.5.5.7.1.1 Criticality=false
AuthInfoAccess [
(0) 1.3.6.1.5.5.7.48.1 URIName: http://nocp4.idm.lab.eng.rdu2.redhat.com:28080/ca/ocsp]
  Extension[2] = ObjectId: 2.5.29.15 Criticality=true
KeyUsage [
  DigitalSignature
  Non_repudiation
  Key_Encipherment
]
  Extension[3] = oid=2.5.29.37  val=48 20 6 8 43 6 1 5 5 7 3 2 6 8 43 6 1 5 5 7 3 4 
]
  Algorithm: [SHA384withEC]
  Signature:
30 64 02 30 04 DD BF 58 36 12 61 AD 26 C2 03 0B AB BF 67 33 
ED 22 E7 8A 0F 3D 1D F6 03 89 D7 83 22 83 F1 95 C9 12 D5 8A 
4B ED 08 45 7C 05 AE DF 6B 46 EC 4E 02 30 12 F9 2B 61 CD 7A 
8B 0B D1 CC 6A C1 87 19 0E 85 E6 64 BE 86 41 CF 4A D5 61 02 
0C B4 FA DE 0E 4E 3B 1D FA 38 D8 55 EF 3A C1 A0 E8 9C 64 90 
B8 C4
], authManagerId=CMCUserSignedAuth}
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMSServlet auditGroupID: groupID: null
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: AAclAuthz.checkPermission(certServer.ee.profile, submit)
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: checkAllowEntries(): expressions: user="anybody"
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: evaluating expressions: user="anybody"
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: evaluated expression: user="anybody" to be true
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: DirAclAuthz: authorization passed
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SignedAuditLogger: event AUTHZ
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SignedAuditLogger: event CMC_REQUEST_RECEIVED
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: createRequests: begins
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: starts
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: getPKIDataFromCMCblob: starts
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: getPKIDataFromCMCblob: cmc request content is signed data
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: authManagerId =CMCUserSignedAuth
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: numcontrols=3
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: about to pre-process controls
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: id_cmc_idPOPLinkRandom found
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC:  id_cmc_identification found
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC:  id_cmc_identityProofV2 found
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: processing controls...
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: not pre-signed CMC request; calling verifyIdentityProofV2;
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile:verifyIdentityProofV2:  begins
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SharedSecret.getSharedToken(String identification): begins.
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SharedSecret.getSharedToken(String identification): searching for identification =user3a; mShrTokAttr =shrTokTesting
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: In LdapBoundConnFactory::getConn()
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: masterConn is connected: true
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: getConn: conn is connected true
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: getConn: mNumConns now 4
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SharedSecret.getSharedToken(String identification):  got entryShrTok
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SharedSecret.decryptShrTokData: wrapped session key retrieved
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SharedSecret.decryptShrTokData: wrapped passphrase retrieved
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SharedSecret.getSharedToken(String identification): returning
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: returnConn: mNumConns now 5
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile:verifyDigest: in verifyDigest: hashAlg=SHA-512 Message Digest from Mozilla-JSS, <initialized>
; macAlg=SHA-256 Message Digest from Mozilla-JSS, <initialized>

[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile:verifyDigest:  The content of two HMAC digest are the same.
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile:verifyIdentityProofV2: current auditSubjectID was:$Unidentified$
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile:verifyIdentityProofV2: identity verified. Updating auditSubjectID
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile:verifyIdentityProofV2: updated auditSubjectID is:user3a
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: passed verifyIdentityProofV2; Proof of Identity successful;
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: got randomSeed
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: found numOfOtherMsgs: 0
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: getting :cmc.popLinkWitnessRequired
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: popLinkWitness(V2) not required
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: nummsgs =1
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: parseCMC: ends
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: createRequests: parseCMC returns cmc_msgs num_requests=1
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: Repository: in getNextSerialNumber. 
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: Repository: checkRange  mLastSerialNo=22
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: Repository: getNextSerialNumber: returning retSerial 22
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: setDefaultCertInfo: setting issuerDN using exact CA signing cert subjectDN encoding
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: createEnrollmentRequest 22
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: createRequests: setting cmc TaggedRequest in request
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet profileSetid=cmcUserCertSet
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: request 22
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: populating request inputs
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCCertReqInput: populate: begins
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: getPKIDataFromCMCblob: starts
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: getPKIDataFromCMCblob: cmc request content is signed data
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CMCCertReqInput: populate: pkiData.getReqSequence() called; nummsgs =1
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: fillTaggedRequest: begins
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: fillTaggedRequest: CRMF:  TaggedRequest type == crmf
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: fillTaggedRequest: CRMF: getting :cmc.lraPopWitness.verify.allow
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: fillTaggedRequest: CRMF: cmc.lraPopWitness.verify.allow is false
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: fillTaggedRequest: CRMF:  hasPop true
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: verifyPOP: for signing keys begins.
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: verifyPOP: POP verification using internal token
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SignedAuditLogger: event PROOF_OF_POSSESSION
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: verifyPOP: done.
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: fillCertReqMsg: Start parseCertReqMsg 
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile:  validity not supplied
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: fillCertReqMsg: found extension:{2 5 29 14}
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: fillCertReqMsg: found SUBJECT_KEY_IDENTIFIER extension
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: populate: begins
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: BasicProfile: populate: policy setid =cmcUserCertSet
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: UserSubjectNameDefault: start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: UserSubjectNameDefault: end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: ValidityDefault: start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ValidityDefault: start time: 0
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ValidityDefault: not before: Fri Jun 15 11:47:12 EDT 2018
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ValidityDefault: range: 180
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ValidityDefault: range unit: day
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ValidityDefault: not after: Wed Dec 12 11:47:12 EST 2018
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: ValidityDefault: end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: UserKeyDefault: start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: UserKeyDefault: end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: AuthorityKeyIdentifierExtDefault: start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: AuthorityKeyIdentifierExtDefault: end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: AuthInfoAccessExtDefault: start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: AuthInfoAccess: createExtension i=0
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: AuthInfoAccessExtDefault: end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: KeyUsageExtDefault: start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: KeyUsageExtDefault: end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: ExtendedKeyUsageExtDefault: start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: ExtendedKeyUsageExtDefault: end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: SigningAlgDefault: start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollDefault: populate: SigningAlgDefault: end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.profileapprovedby$ value=admin
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.auth_token.cmcselfsigned$ value=true
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.authenticatedname$ value=
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.cert_request$ value=oYIDHDCCAsACAQEwgZ6AAQKlHzAdMRswGQYKCZImiZPyLGQBARMLdGVzdHVzZXIx
MDCmWTATBgcqhkjOPQIBBggqhkjOPQMBBwNCAATLmbMbReUO1fOv9kuOjFLMyxDI
2+wBLw7L3dAoWnFgwg4knBDmdUuinaRp12h5w56DD5RzLULsCZKf/AgqPU6dqR0w
GwYDVR0OBBRRUCdNDgHU9Cvdj4hl7bQEYUiWejCCAhgwggHLBgkrBgEFBQcFAQSg
ggG8MIIBuKEdBglghkgBZQMEAQIEEDbl+fBqlyDomYIYVGprU9GCggEBACVIRijZ
9AUviI48G01Y7C/ql1dADzMDqi7dgbNtPxm0dTG7yhPIjsat+HrliC6N7zomfiPC
ngX1fE1aSxZHuYjHeiu04ZJWOsOQ+1/Gm6mE2FagmSQquhwwCh99Wz3vP2zuWf+N
idKmFN9KGTX7fWCUcCtHxT1nOVfVoYkRUYLzHCw/Byn4Q5eX/Cw2dtmSU7rJ4PQD
d3o5fDBIJ1K6o+dpZx7tjU2qUJcLu08WpUQ47wNZUYJtOTfpK6ZQL54RFKQuTVFg
RYqDjCqNhX3Iy3ha0VqE/JO1dQcKqewdefKjdRlRHH3wSq1qojuKHSXoG0MlinBW
rLUkppQXFBi7D9MDgZEAHBQ+hQg/ks4Rg/4TW/kcP0oCQHr5iwVDCAph7ILYSR2j
XTcDkhF4jso9C1Ekjr/QOQ4NNCLmxdpKKTbGkdOT29wPsrKWP59ojkTrYxibkXmi
o3gCilLdA7lsCpACnQBsN80GZTDEIZ/yMEwWRI1seSbLlCBxIIK2NBnA2UVWcQtf
MoG1gjj1oW7NQkLACWwlMEcGCCsGAQUFBwchMDswCwYJYIZIAWUDBAIBMAoGCCqG
SIb3DQIJBCAwftFnhCJ3dlfC1+a9ZNQTOylD0jnlyBht+qf4qGhHqaFWMAoGCCqG
SM49BAMCA0gAMEUCIQCkrT2T/0dUPAVuVfnWTNqZZFDFWho7Yxkv6W1b0aNBiQIg
BBUAP0JPRN14lIjH6agIxFWfmWeeuvDqG0nXM6fq4Iw=

[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.profile$ value=true
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.requestversion$ value=1.0.0
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.req_subject_name.cn$ value=
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.req_locale$ value=en
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.dbstatus$ value=NOT_UPDATED
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.requeststatus$ value=begin
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.req_key$ value=MFkwEwYHKoZIzj0CAQYIKoZIzj0DAQcDQgAEy5mzG0XlDtXzr/ZLjoxSzMsQyNvs
AS8Oy93QKFpxYMIOJJwQ5nVLop2kaddoecOegw+Ucy1C7AmSn/wIKj1OnQ==

[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.auth_token.authmgrinstname$ value=CMCUserSignedAuth
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.auth_token.uid$ value=$Unidentified$
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.auth_token.userid$ value=$Unidentified$
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.auth_token.cert_request_type$ value=cmc-crmf
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.profileid$ value=caECFullCMCSelfSignedCert
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.requestid$ value=22
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.auth_token.tokencertsubject$ value=
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.auth_token.authtime$ value=1529077632324
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.req_x509info$ value=MIIBlKADAgECAgEAMAoGCCqGSM49BAMDMDoxCzAJBgNVBAYTAlVTMRAwDgYDVQQK
EwdDb21wYW55MRkwFwYDVQQDExBDb21wYW55IFJvb3QgQ0EyMB4XDTE4MDYxNTE1
NDcxMloXDTE4MTIxMjE2NDcxMlowHTEbMBkGCgmSJomT8ixkAQETC3Rlc3R1c2Vy
MTAwMFkwEwYHKoZIzj0CAQYIKoZIzj0DAQcDQgAEy5mzG0XlDtXzr/ZLjoxSzMsQ
yNvsAS8Oy93QKFpxYMIOJJwQ5nVLop2kaddoecOegw+Ucy1C7AmSn/wIKj1OnaOB
pzCBpDAfBgNVHSMEGDAWgBR0EMvPl3p8ZpXkr5IQNPAlB1ayFjBSBggrBgEFBQcB
AQRGMEQwQgYIKwYBBQUHMAGGNmh0dHA6Ly9ub2NwNC5pZG0ubGFiLmVuZy5yZHUy
LnJlZGhhdC5jb206MjgwODAvY2Evb2NzcDAOBgNVHQ8BAf8EBAMCA9gwHQYDVR0l
BBYwFAYIKwYBBQUHAwIGCCsGAQUFBwME

[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.req_seq_num$ value=0
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.profilesetid$ value=cmcUserCertSet
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.req_subject_name.uid$ value=testuser100
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.req_archive_options$ value=oIIBvDCCAbihHQYJYIZIAWUDBAECBBA25fnwapcg6JmCGFRqa1PRgoIBAQAlSEYo
2fQFL4iOPBtNWOwv6pdXQA8zA6ou3YGzbT8ZtHUxu8oTyI7Grfh65Yguje86Jn4j
wp4F9XxNWksWR7mIx3ortOGSVjrDkPtfxpuphNhWoJkkKrocMAoffVs97z9s7ln/
jYnSphTfShk1+31glHArR8U9ZzlX1aGJEVGC8xwsPwcp+EOXl/wsNnbZklO6yeD0
A3d6OXwwSCdSuqPnaWce7Y1NqlCXC7tPFqVEOO8DWVGCbTk36SumUC+eERSkLk1R
YEWKg4wqjYV9yMt4WtFahPyTtXUHCqnsHXnyo3UZURx98EqtaqI7ih0l6BtDJYpw
Vqy1JKaUFxQYuw/TA4GRABwUPoUIP5LOEYP+E1v5HD9KAkB6+YsFQwgKYeyC2Ekd
o103A5IReI7KPQtRJI6/0DkODTQi5sXaSik2xpHTk9vcD7Kylj+faI5E62MYm5F5
oqN4AopS3QO5bAqQAp0AbDfNBmUwxCGf8jBMFkSNbHkmy5QgcSCCtjQZwNlFVnEL
XzKBtYI49aFuzUJCwAlsJQ==

[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.profileremoteaddr$ value=10.8.60.16
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.requesttype$ value=enrollment
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.req_extensions$ value=oyEwHzAdBgNVHQ4EFgQUUVAnTQ4B1PQr3Y+IZe20BGFIlno=

[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.req_transport_cert$ value=MIIDIjCCAqegAwIBAgIBBzAKBggqhkjOPQQDAzA6MQswCQYDVQQGEwJVUzEQMA4GA1UEChMHQ29tcGFueTEZMBcGA1UEAxMQQ29tcGFueSBSb290IENBMjAeFw0xODA2MTUxMjU5MTFaFw0yMDA2MDQxMjU5MTFaMG8xJDAiBgNVBAoMG2V4YW1wbGUuY29tIFNlY3VyaXR5IERvbWFpbjEjMCEGA1UECwwaZ2thcG9vcl9SSENTNzVfa3JhLWVjYy11cDIxIjAgBgNVBAMMGURSTSBUcmFuc3BvcnQgQ2VydGlmaWNhdGUwggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQCohwK3TDFb6iqCn26zx+BN7d/3OC0k4+7OtorOQp7r/RJ+9ctapQy8sPN5l0awRqKo2TZaDz40BCUP1WkWvglVyNTBoZrFqwh4lLdCGZxVeSZv3tAUx4wpT5sDJH6RPXqgahBZaIgkgcj8GOKwQKxmUQREMEFxosbZOxQA7mqQdrJia/N1g03Uv5xBj0CMPpsEiZS9ZnzscBPgwh/VyF29XLyWZp2VhjeMa+6dF1wTyGXH86ZYGm6kTHsbt3vPihIXe2A4KEhcNYnPXXc/HKAuC1jIaObBzS4TXpjjSYfKHkE1o0lQ9KM/6PeoOQQJgGXfWWqcJet0jyk7coORWhsPAgMBAAGjgZ0wgZowHwYDVR0jBBgwFoAUdBDLz5d6fGaV5K+SEDTwJQdWshYwUgYIKwYBBQUHAQEERjBEMEIGCCsGAQUFBzABhjZodHRwOi8vbm9jcDQuaWRtLmxhYi5lbmcucmR1Mi5yZWRoYXQuY29tOjI4MDgwL2NhL29jc3AwDgYDVR0PAQH/BAQDAgTwMBMGA1UdJQQMMAoGCCsGAQUFBwMCMAoGCCqGSM49BAMDA2kAMGYCMQDAlIbZByl/0Vk//ei/M/bC3MnfPvEDADEvzPvPpUYclWJCsAXgz6X353KLGxJN/B8CMQCNYaRoKZ4cnLCpQI3HQg2jKtrQoDzN702ZmB4+x5A9QoLdZ8jUudaW568/W8rAh+A=
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.req_subject_name$ value=MB0xGzAZBgoJkiaJk/IsZAEBEwt0ZXN0dXNlcjEwMA==

[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.bodypartid$ value=1
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: key=$request.profileremotehost$ value=10.8.60.16
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: submit: begins
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: submit: popChallengeRequired =false
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: In LdapBoundConnFactory::getConn()
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: masterConn is connected: true
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: getConn: conn is connected true
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: getConn: mNumConns now 2
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: returnConn: mNumConns now 3
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile: submit:  auth token is not null
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile.validate: start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile.validate: cert subject name:UID=testuser100
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SignedAuditLogger: event PROFILE_CERT_REQUEST
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: BasicProfile: validate start on setId=cmcUserCertSet
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SubjectNameConstraint: validate start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SubjectNameConstraint: validate start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SubjectNameConstraint: validate cert subject =UID=testuser100
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SubjectNameConstraint: validate() - sn500 dname = UID=testuser100
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SubjectNameConstraint: validate end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ValidityConstraint: validate start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ValidityConstraint: not before: Fri Jun 15 11:47:12 EDT 2018
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ValidityConstraint: not after: Wed Dec 12 11:47:12 EST 2018
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ValidityConstraint: range: 365
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ValidityConstraint: range unit: day
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ValidityConstraint: limit: Sat Jun 15 11:47:12 EDT 2019
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: ValidityConstraint: validate end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: KeyConstraint: validate start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: vect: [nistp256, secp256r1]
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: keyParams[i]: 0 param: nistp256
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: KeyConstraint.validate: EC key constrainst passed.
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: KeyConstraint: validate end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: KeyUsageExtConstraint: validate start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: KeyUsageExtConstraint: validate end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SigningAlgConstraint: validate start
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: SigningAlgConstraint: validate end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: BasicProfile: change to pending state
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: BasicProfile: validate end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: EnrollProfile.validate: end
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CAEnrollProfile: execute request ID 22
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CAEnrollProfile: execute found PKIArchiveOptions
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: CAEnrollProfile: execute send request
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: HttpPKIMessage.fromRequest: requestId=22 requestStatus=pending instance=com.netscape.cmscore.request.EnrollmentRequest@305741b2
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: RequestTransfer: profile request id = 22
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: RequestTransfer: attribute size=32
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: Before synch
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: In HttpConnFactory.getConn
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: HttpgetConn: mNumConns now 0
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: HttpConnector.send com.netscape.cmscore.connector.HttpConnection@18a8299e
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: in HttpConnection.send com.netscape.cmscore.connector.HttpConnection@18a8299e
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: writeObject
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: HttpConnection.doSend: with String content length: 6358
[15/Jun/2018:11:47:12][http-bio-28443-exec-10]: HttpConnection: Connecting to nocp4.idm.lab.eng.rdu2.redhat.com:31443 with timeout 30s
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: HttpConnection: Connected to nocp4.idm.lab.eng.rdu2.redhat.com:31443
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: HttpConnection.doSend: sending request
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: HttpConnection.doSend: server returned status 200
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: HttpConnection.send response: got content
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: HttpConn:decoded reply
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: HttpConncter.send has been called
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: reply request id 4
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: reply request type enrollment
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: reply status complete
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: HttpPKMessage.toRequest: requestStatus=pending
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: remote request id 22 was completed
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: In HttpConnFactory.returnConn
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: HttpreturnConn: mNumConns now 1
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: SignedAuditLogger: event SECURITY_DATA_ARCHIVAL_REQUEST
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: LogFile: event type not selected: SECURITY_DATA_ARCHIVAL_REQUEST
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: issueX509Cert
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: dnUTF8Encoding false
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: CertificateRepository: getNextSerialNumber  mEnableRandomSerialNumbers=false
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: Repository: in getNextSerialNumber. 
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: Repository: checkRange  mLastSerialNo=17
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: Repository: getNextSerialNumber: returning retSerial 17
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: CAService: issueX509Cert: setting issuerDN using exact CA signing cert subjectDN encoding
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: About to ca.sign cert.
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: sign cert get algorithm
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: sign cert encoding cert
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: sign cert encoding algorithm
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: CA cert signing: signing cert
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: Getting algorithm context for SHA384withEC ECSignatureWithSHA384Digest
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: Signing Certificate
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: storeX509Cert 17
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: In storeX509Cert
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: In LdapBoundConnFactory::getConn()
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: masterConn is connected: true
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: getConn: conn is connected true
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: getConn: mNumConns now 2
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: returnConn: mNumConns now 3
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: done storeX509Cert
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: SignedAuditLogger: event CERT_REQUEST_PROCESSED
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: In LdapBoundConnFactory::getConn()
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: masterConn is connected: true
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: getConn: conn is connected true
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: getConn: mNumConns now 2
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: returnConn: mNumConns now 3
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: ARequestNotifier  notify mIsPublishingQueueEnabled=false mMaxThreads=1
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: ProfileSubmitCMCServlet: done serving
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: CMCOutputTemplate: createFullResponse: begins with cert_request_type=cmc
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: CMCOutputTemplate: createFullResponse:  processing cmc
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: CMCOutputTemplate: createFullResponse:  error_codes[0]=0
[15/Jun/2018:11:47:13][Thread-16]: RunListeners:: noQueue  SingleRequest
[15/Jun/2018:11:47:13][Thread-16]: RunListeners: IRequestListener = com.netscape.cms.listeners.CertificateIssuedListener
[15/Jun/2018:11:47:13][Thread-16]: CertificateIssuedListener: accept 22
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: CMCOutputTemplate: createFullResponse:  processing controls
[15/Jun/2018:11:47:13][Thread-16]: RunListeners: IRequestListener = com.netscape.ca.CRLIssuingPoint$RevocationRequestListener
[15/Jun/2018:11:47:13][Thread-16]: RunListeners: IRequestListener = com.netscape.cms.listeners.CertificateRevokedListener
[15/Jun/2018:11:47:13][Thread-16]: RunListeners:  noQueue  SingleRequest
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: CMCOutputTemplate: createFullResponse:  after new ResponseBody, respBody not null
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: CMCOutputTemplate: getContentInfo: begins
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: CMCOutputTemplate: getContentInfo:  - done
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: SignedAuditLogger: event CMC_RESPONSE_SENT
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: CMCOutputTemplate: createFullResponse: ends
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: CMSServlet: curDate=Fri Jun 15 11:47:13 EDT 2018 id=caProfileSubmitCMCFull time=1564
[15/Jun/2018:11:47:13][http-bio-28443-exec-10]: SignedAuditLogger: event ACCESS_SESSION_TERMINATED




Debug logs for KRA


[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: returnConn: mNumConns now 3
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: EnrollmentService: key record 0x4 (UID=testuser100) archived
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: SignedAuditLogger: event SECURITY_DATA_ARCHIVAL_REQUEST_PROCESSED
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: In LdapBoundConnFactory::getConn()
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: masterConn is connected: true
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: getConn: conn is connected true
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: getConn: mNumConns now 2
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: returnConn: mNumConns now 3
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: In LdapBoundConnFactory::getConn()
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: masterConn is connected: true
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: getConn: conn is connected true
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: getConn: mNumConns now 2
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: returnConn: mNumConns now 3
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: ARequestNotifier  notify mIsPublishingQueueEnabled=false mMaxThreads=1
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: SignedAuditLogger: event CERT_REQUEST_PROCESSED
[15/Jun/2018:11:47:13][Thread-15]: RunListeners:: noQueue  SingleRequest
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: LogFile: event type not selected: CERT_REQUEST_PROCESSED
[15/Jun/2018:11:47:13][Thread-15]: RunListeners:  noQueue  SingleRequest
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: HttpPKIMessage.fromRequest: requestId=4 requestStatus=complete instance=com.netscape.cmscore.request.EnrollmentRequest@7066b3c0
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: RequestTransfer: profile request id = 4
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: RequestTransfer: attribute size=35
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: ConnectorServlet: replymsg.reqStatus=complete
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: ConnectorServlet: done requestId=4
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: SignedAuditLogger: event INTER_BOUNDARY
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: LogFile: event type not selected: INTER_BOUNDARY
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: ConnectorServlet: done processRequest
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: writeObject
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: ConnectorServlet: send response RA_Id=CN=Subsystem Certificate,OU=gkapoor-ecc-exca-cmc-ex,O=example.com Security Domain
[15/Jun/2018:11:47:13][http-bio-31443-exec-24]: SignedAuditLogger: event ACCESS_SESSION_TERMINATED



Signed audit for CA

0.http-bio-28443-exec-10 - [15/Jun/2018:11:47:12 EDT] [14] [6] [AuditEvent=ACCESS_SESSION_ESTABLISH][ClientIP=10.8.60.16][ServerIP=10.8.60.16][SubjectID=UID=test10,CN=test10,O=example.org][Outcome=Success] access session establish success
0.http-bio-28443-exec-10 - [15/Jun/2018:11:47:12 EDT] [14] [6] [AuditEvent=AUTHZ][SubjectID=$Unidentified$][Outcome=Success][aclResource=certServer.ee.profile][Op=submit] authorization success
0.http-bio-28443-exec-10 - [15/Jun/2018:11:47:12 EDT] [14] [6] [AuditEvent=CMC_REQUEST_RECEIVED][SubjectID=$Unidentified$][Outcome=Success][CMCRequest=MIIE+QYJKoZIhvcNAQcCoIIE6jCCBOYCAQMxDzANBglghkgBZQMEAgEFADCCA/sGCCsGAQUFBwwCoIID7QSCA+kwggPlMIG6MFECAQEGCCsGAQUFBwcWMUIEQNssIpdWU7Q/wOJ71iswL22BcsTKUdJLZ063agJlvWumqoqdNJ4gQMuUdMIGKoPu0t8AlRcudt/+FJ1HbLC+wKYwFwIBAQYIKwYBBQUHBwIxCAwGdXNlcjNhMEwCAQIGCCsGAQUFBwciMT0wOzALBglghkgBZQMEAgMwCgYIKoZIhvcNAgkEILwP5vZd2a/9W6AINuSvFuR2BABZYlKyHyVhMj+XklMVMIIDIKGCAxwwggLAAgEBMIGegAECpR8wHTEbMBkGCgmSJomT8ixkAQETC3Rlc3R1c2VyMTAwplkwEwYHKoZIzj0CAQYIKoZIzj0DAQcDQgAEy5mzG0XlDtXzr/ZLjoxSzMsQyNvsAS8Oy93QKFpxYMIOJJwQ5nVLop2kaddoecOegw+Ucy1C7AmSn/wIKj1OnakdMBsGA1UdDgQUUVAnTQ4B1PQr3Y+IZe20BGFIlnowggIYMIIBywYJKwYBBQUHBQEEoIIBvDCCAbihHQYJYIZIAWUDBAECBBA25fnwapcg6JmCGFRqa1PRgoIBAQAlSEYo2fQFL4iOPBtNWOwv6pdXQA8zA6ou3YGzbT8ZtHUxu8oTyI7Grfh65Yguje86Jn4jwp4F9XxNWksWR7mIx3ortOGSVjrDkPtfxpuphNhWoJkkKrocMAoffVs97z9s7ln/jYnSphTfShk1+31glHArR8U9ZzlX1aGJEVGC8xwsPwcp+EOXl/wsNnbZklO6yeD0A3d6OXwwSCdSuqPnaWce7Y1NqlCXC7tPFqVEOO8DWVGCbTk36SumUC+eERSkLk1RYEWKg4wqjYV9yMt4WtFahPyTtXUHCqnsHXnyo3UZURx98EqtaqI7ih0l6BtDJYpwVqy1JKaUFxQYuw/TA4GRABwUPoUIP5LOEYP+E1v5HD9KAkB6+YsFQwgKYeyC2Ekdo103A5IReI7KPQtRJI6/0DkODTQi5sXaSik2xpHTk9vcD7Kylj+faI5E62MYm5F5oqN4AopS3QO5bAqQAp0AbDfNBmUwxCGf8jBMFkSNbHkmy5QgcSCCtjQZwNlFVnELXzKBtYI49aFuzUJCwAlsJTBHBggrBgEFBQcHITA7MAsGCWCGSAFlAwQCATAKBggqhkiG9w0CCQQgMH7RZ4Qid3ZXwtfmvWTUEzspQ9I55cgYbfqn+KhoR6mhVjAKBggqhkjOPQQDAgNIADBFAiEApK09k/9HVDwFblX51kzamWRQxVoaO2MZL+ltW9GjQYkCIAQVAD9CT0TdeJSIx+moCMRVn5lnnrrw6htJ1zOn6uCMMAAwAKAAMYHOMIHLAgEDgBRRUCdNDgHU9Cvdj4hl7bQEYUiWejANBglghkgBZQMEAgEFAKBKMBcGCSqGSIb3DQEJAzEKBggrBgEFBQcMAjAvBgkqhkiG9w0BCQQxIgQgrIVA8xghAZQkz6jtpagAzwQ3HVnksXsxjSsd/1VZqFgwDAYIKoZIzj0EAwIFAARHMEUCIQC4Xv+ItI9a47QNlzhX63d/sO3ipbmL68tBvaZ3nGb4iQIgBkOcUJHprUBcaDXOjQUVo/9IRs0oFf46CDu0YZ2TOzg=] CMC request received
0.http-bio-28443-exec-10 - [15/Jun/2018:11:47:12 EDT] [14] [6] [AuditEvent=PROOF_OF_POSSESSION][SubjectID=user3a][Outcome=Success][Info=method=EnrollProfile: verifyPOP: ] proof of possession
0.http-bio-28443-exec-10 - [15/Jun/2018:11:47:12 EDT] [14] [6] [AuditEvent=PROFILE_CERT_REQUEST][SubjectID=user3a][Outcome=Success][ReqID=22][ProfileID=caECFullCMCSelfSignedCert][CertSubject=UID=testuser100] certificate request made with certificate profiles
0.http-bio-28443-exec-10 - [15/Jun/2018:11:47:13 EDT] [14] [6] [AuditEvent=CERT_REQUEST_PROCESSED][SubjectID=$Unidentified$][Outcome=Success][ReqID=22][CertSerialNum=17] certificate request processed
0.http-bio-28443-exec-10 - [15/Jun/2018:11:47:13 EDT] [14] [6] [AuditEvent=CMC_RESPONSE_SENT][SubjectID=user3a][Outcome=Success][CMCResponse=MIIJEgYJKoZIhvcNAQcCoIIJAzCCCP8CAQMxDzANBglghkgBZQMEAgIFADAxBggrBgEFBQcMA6AlBCMwITAbMBkCAQEGCCsGAQUFBwcZMQowCAIBADADAgEBMAAwAKCCB1YwggIPMIIBlKADAgECAgERMAoGCCqGSM49BAMDMDoxCzAJBgNVBAYTAlVTMRAwDgYDVQQKEwdDb21wYW55MRkwFwYDVQQDExBDb21wYW55IFJvb3QgQ0EyMB4XDTE4MDYxNTE1NDcxMloXDTE4MTIxMjE2NDcxMlowHTEbMBkGCgmSJomT8ixkAQETC3Rlc3R1c2VyMTAwMFkwEwYHKoZIzj0CAQYIKoZIzj0DAQcDQgAEy5mzG0XlDtXzr/ZLjoxSzMsQyNvsAS8Oy93QKFpxYMIOJJwQ5nVLop2kaddoecOegw+Ucy1C7AmSn/wIKj1OnaOBpzCBpDAfBgNVHSMEGDAWgBR0EMvPl3p8ZpXkr5IQNPAlB1ayFjBSBggrBgEFBQcBAQRGMEQwQgYIKwYBBQUHMAGGNmh0dHA6Ly9ub2NwNC5pZG0ubGFiLmVuZy5yZHUyLnJlZGhhdC5jb206MjgwODAvY2Evb2NzcDAOBgNVHQ8BAf8EBAMCA9gwHQYDVR0lBBYwFAYIKwYBBQUHAwIGCCsGAQUFBwMEMAoGCCqGSM49BAMDA2kAMGYCMQCZE9VkS+INhR33ChHgBDBsf+ty2dNbqzyFtx26CVay78pxuyfH0SR4UIVyCVb+34kCMQCbmp3K2/3RShNmQdey59Re/RKdQ1SasXLpZdcq7oJzcgVE+DdrdtjRAzebQ/0UxQYwggKIMIICDqADAgECAgQG0t0hMAoGCCqGSM49BAMDMGYxHjAcBgNVBAoMFUV4YW1wbGUtcmhjczkyLUNBLWVjYzEjMCEGA1UECwwaZ2thcG9vcl9SSENTNzVfdXBkYXRlMl9lY2MxHzAdBgNVBAMMFkNBIFNpZ25pbmcgQ2VydGlmaWNhdGUwHhcNMTgwNjEzMTY1NDExWhcNMzgwMzA1MTc1NDExWjA6MQswCQYDVQQGEwJVUzEQMA4GA1UEChMHQ29tcGFueTEZMBcGA1UEAxMQQ29tcGFueSBSb290IENBMjB2MBAGByqGSM49AgEGBSuBBAAiA2IABHOWGZ6m6jFISsSlgzdbMO6C6F9usn14iKEw9G2Zo0DPhr1HSglsZhJI/vxEAM//AUINhcyJUzxGkv1ftFqRuvrhTuKTAMhRT1Lx9gGJBO3GVZ+jCysp8oHpcXBNqwTOzqOBuDCBtTAfBgNVHSMEGDAWgBQuk8VRXk5A+iq3vqqIxi/dHAG/fjAPBgNVHRMBAf8EBTADAQH/MA4GA1UdDwEB/wQEAwIBxjAdBgNVHQ4EFgQUdBDLz5d6fGaV5K+SEDTwJQdWshYwUgYIKwYBBQUHAQEERjBEMEIGCCsGAQUFBzABhjZodHRwOi8vbm9jcDQuaWRtLmxhYi5lbmcucmR1Mi5yZWRoYXQuY29tOjIwMDgwL2NhL29jc3AwCgYIKoZIzj0EAwMDaAAwZQIxALbOB1JYbxPSfJnzHwfJEg2ogsuTBHeSEcORVyaBrk1tNHKUIu15PFGKjDiKRx4BtAIwHSi8JtGjJo2n8SCkgXrXEcFOYuq0YfAHioRpqqFdEymrruxhrd2wxywmkteGZGadMIICszCCAjqgAwIBAgIEBdDGmDAKBggqhkjOPQQDAzBmMR4wHAYDVQQKDBVFeGFtcGxlLXJoY3M5Mi1DQS1lY2MxIzAhBgNVBAsMGmdrYXBvb3JfUkhDUzc1X3VwZGF0ZTJfZWNjMR8wHQYDVQQDDBZDQSBTaWduaW5nIENlcnRpZmljYXRlMB4XDTE4MDUyNTEwMzMyN1oXDTM4MDUyNTEwMzMyN1owZjEeMBwGA1UECgwVRXhhbXBsZS1yaGNzOTItQ0EtZWNjMSMwIQYDVQQLDBpna2Fwb29yX1JIQ1M3NV91cGRhdGUyX2VjYzEfMB0GA1UEAwwWQ0EgU2lnbmluZyBDZXJ0aWZpY2F0ZTB2MBAGByqGSM49AgEGBSuBBAAiA2IABObj2RAcm9/fS5wQet/ithLdKvmfQEkjGJcX12wXADQVmdicLU4WY8mdknG0uOol14S178FrR0EfPZbVmhBChKPbpSn4ILN2bN0NR1MvjX2jaLBrFwtexkVn+whPXnzkE6OBuDCBtTAfBgNVHSMEGDAWgBQuk8VRXk5A+iq3vqqIxi/dHAG/fjAPBgNVHRMBAf8EBTADAQH/MA4GA1UdDwEB/wQEAwIBxjAdBgNVHQ4EFgQULpPFUV5OQPoqt76qiMYv3RwBv34wUgYIKwYBBQUHAQEERjBEMEIGCCsGAQUFBzABhjZodHRwOi8vbm9jcDQuaWRtLmxhYi5lbmcucmR1Mi5yZWRoYXQuY29tOjIwMDgwL2NhL29jc3AwCgYIKoZIzj0EAwMDZwAwZAIwRtWeH6EbCbfMOzD20bGl+awlHGuFRwYpBbwG/u7MCYywcTeTQvmsEfOuB8TvsADhAjBPyQi1xvgLrElfjmzh6VTfXi4xqNi2bYJJELG9ZPh2L1PhpAy3a02jrEH9UNM4S9UxggFaMIIBVgIBATBuMGYxHjAcBgNVBAoMFUV4YW1wbGUtcmhjczkyLUNBLWVjYzEjMCEGA1UECwwaZ2thcG9vcl9SSENTNzVfdXBkYXRlMl9lY2MxHzAdBgNVBAMMFkNBIFNpZ25pbmcgQ2VydGlmaWNhdGUCBAbS3SEwDQYJYIZIAWUDBAICBQCgWjAXBgkqhkiG9w0BCQMxCgYIKwYBBQUHDAMwPwYJKoZIhvcNAQkEMTIEMEem8h5SGlF1pQCzfM+7OZRKcXqqv6vAgePVzmvT+kvcLoZxZWR01B+qrvUTmwodUjAMBggqhkjOPQQDAwUABGgwZgIxAOTV/O7MJs++lROnNOv6T+rA3Fdnfd2v+UFyVPDDQhRuXgj+3AEb3KWvI1azZ3YfKQIxAPTIGuMZ91tf9MOpr+03AG9TMQLX15/dLb5QB+XATnXhvUnY+PNv6YCi3t+cDDyK9A==] CMC response sent
0.http-bio-28443-exec-10 - [15/Jun/2018:11:47:13 EDT] [14] [6] [AuditEvent=ACCESS_SESSION_TERMINATED][ClientIP=10.8.60.16][ServerIP=10.8.60.16][SubjectID=UID=test10,CN=test10,O=example.org][Outcome=Success][Info=CLOSE_NOTIFY] access session terminated





Signed audit for KRA

0.http-bio-31443-exec-24 - [15/Jun/2018:11:47:13 EDT] [14] [6] [AuditEvent=ACCESS_SESSION_ESTABLISH][ClientIP=10.8.60.16][ServerIP=10.8.60.16][SubjectID=CN=Subsystem Certificate,OU=gkapoor-ecc-exca-cmc-ex,O=example.com Security Domain][Outcome=Success] access session establish success
0.http-bio-31443-exec-24 - [15/Jun/2018:11:47:13 EDT] [14] [6] [AuditEvent=AUTH][SubjectID=CA-nocp4.idm.lab.eng.rdu2.redhat.com-28443][Outcome=Success][AuthMgr=certUserDBAuthMgr] authentication success
0.http-bio-31443-exec-24 - [15/Jun/2018:11:47:13 EDT] [14] [6] [AuditEvent=AUTHZ][SubjectID=CA-nocp4.idm.lab.eng.rdu2.redhat.com-28443][Outcome=Success][aclResource=certServer.kra.connector][Op=submit] authorization success
0.http-bio-31443-exec-24 - [15/Jun/2018:11:47:13 EDT] [14] [6] [AuditEvent=ROLE_ASSUME][SubjectID=CA-nocp4.idm.lab.eng.rdu2.redhat.com-28443][Outcome=Success][Role=Trusted Managers] assume privileged role
0.http-bio-31443-exec-24 - [15/Jun/2018:11:47:13 EDT] [14] [6] [AuditEvent=PROFILE_CERT_REQUEST][SubjectID=CA-nocp4.idm.lab.eng.rdu2.redhat.com-28443][Outcome=Success][ReqID=22][ProfileID=kraConnector][CertSubject=UID=testuser100] certificate request made with certificate profiles
0.http-bio-31443-exec-24 - [15/Jun/2018:11:47:13 EDT] [14] [6] [AuditEvent=ACCESS_SESSION_TERMINATED][ClientIP=10.8.60.16][ServerIP=10.8.60.16][SubjectID=CN=Subsystem Certificate,OU=gkapoor-ecc-exca-cmc-ex,O=example.com Security Domain][Outcome=Success][Info=CLOSE_NOTIFY] access session terminated




Verification 2: Check KRA agent page if archival happens.

1 	complete 		UID=testuser
2 	complete 		UID=testuser
3 	complete 		UID=testuser1
4 	complete 		UID=testuser100

Request 4
Request
Status:	complete
Type:	enrollment
Created on:	6/15/2018, 9:17:13 PM
Updated by:	CA-nocp4.idm.lab.eng.rdu2.redhat.com-28443
Updated on:	6/15/2018, 9:17:13 PM
Archival Information
Public key:	30:59:30:13:06:07:2A:86:48:CE:3D:02:01:06:08:2A:86:48:CE:3D: 03:01:07:03:42:00:04:CB:99:B3:1B:45:E5:0E:D5:F3:AF:F6:4B:8E: 8C:52:CC:CB:10:C8:DB:EC:01:2F:0E:CB:DD:D0:28:5A:71:60:C2:0E: 24:9C:10:E6:75:4B:A2:9D:A4:69:D7:68:79:C3:9E:83:0F:94:73:2D: 42:EC:09:92:9F:FC:08:2A:3D:4E:9D
Owner name:	UID=testuser100
Key identifier:	4


Test Case 2: Run CMC/Http with CRMFPopClient without -a and request.selfSign=true
===============================================================================


1. CRMFPopClient -d subca-db/ -p SECret.123 -n UID=testuser100 -b transport.pem   -y  -w "AES/CBC/PKCS5Padding" -o crmf2.req

-- The csr is rsa.


2. Run CMC request.


3. Run HttpClient. This Httpclient send it to servlet=/ca/ee/ca/profileSubmitCMCFull?profileId=caECFullCMCSelfSignedCert.
So expected result should be fail because key will not match.

4. CMCResponse:

Number of controls is 1
Control #0: CMCStatusInfoV2
   OID: {1 3 6 1 5 5 7 7 25}
   BodyList: 0 
   Status String: Request Key Type EC Not Matched Rejected - {1}
   OtherInfo type: FAIL
     failInfo=internal ca error
ERROR: CMC status for [0]: failed

CA debug logs:

[15/Jun/2018:11:53:13][http-bio-28443-exec-11]: ProfileSubmitCMCServlet: submit Key Type EC Not Matched
[15/Jun/2018:11:53:13][http-bio-28443-exec-11]: In LdapBoundConnFactory::getConn()
[15/Jun/2018:11:53:13][http-bio-28443-exec-11]: masterConn is connected: true

CA Signed audit logs:

0.http-bio-28443-exec-11 - [15/Jun/2018:11:53:13 EDT] [14] [6] [AuditEvent=CERT_REQUEST_PROCESSED][SubjectID=$Unidentified$][Outcome=Failure][ReqID=23][InfoName=rejectReason][InfoValue=Request Key Type EC Not Matched Rejected - {1}] certificate request processed

Comment 13 Geetika Kapoor 2018-06-15 16:03:31 UTC

Original Test case works fine.
 I Think Test case 2 is failing which looks as expected.Christina test case 2 failure looks fine to you?

Comment 14 Christina Fu 2018-06-15 20:56:48 UTC

Yes test 2 result is expected.  Without specifying "-a ec", it defaults to RSA.  The key is going to mismatch with the ECC profile.

Comment 16 errata-xmlrpc 2018-06-26 16:47:59 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2018:1979