Bug 1525306

Summary: CC: missing CMC request and response record
Product: Red Hat Enterprise Linux 7 Reporter: Christina Fu <cfu>
Component: pki-coreAssignee: Christina Fu <cfu>
Status: CLOSED ERRATA QA Contact: Asha Akkiangady <aakkiang>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 7.5CC: cfu, gkapoor, jreznik, lmiksik, mharmsen
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: pki-core-10.5.1-7.el7 Doc Type: No Doc Update
Doc Text:
https://bugzilla.redhat.com/show_bug.cgi?id=1518180#c7
 Story Points: ---
Clone Of: Environment:
Last Closed: 2018-04-10 17:02:54 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Christina Fu 2017-12-13 02:33:49 UTC 
this came up in ST review.  for FIA_CMCS_EXT.1, it is required to store signed CMC requests received, and signed CMC responses sent.
RHCS currently does not literally record the actual signed CMC requests and responses.  I have verified with Gossamer that we CAN do either of the following:
* Logged as audit events.
* Recorded into corresponding request records.
I specifically asked for this because it would seem more useful to save the CMC requests in the request records instead.
Comment 3 Christina Fu 2018-02-03 01:31:04 UTC 
https://pagure.io/dogtagpki/issue/2880#comment-491898
Comment 5 Geetika Kapoor 2018-02-15 11:25:40 UTC 
Test Case 1 : Perform an operation and check audit logs for CMC
Verification: Make sure CMC_REQUEST_RECEIVED and CMC_RESPONSE_SENT exist. However subjectid is still unidentified.Is it okay to have like that?


0.http-bio-25443-exec-3 - [15/Feb/2018:05:44:49 EST] [14] [6] [AuditEvent=ACCESS_SESSION_ESTABLISH][ClientIP=10.12.28.208][ServerIP=10.12.28.208][SubjectID=UID=sslauth,OU=People][Outcome=Success] access session establish success
0.http-bio-25443-exec-3 - [15/Feb/2018:05:44:49 EST] [14] [6] [AuditEvent=AUTHZ][SubjectID=$Unidentified$][Outcome=Success][aclResource=certServer.ee.profile][Op=submit] authorization success
0.http-bio-25443-exec-3 - [15/Feb/2018:05:44:49 EST] [14] [6] [AuditEvent=CMC_REQUEST_RECEIVED][SubjectID=$Unidentified$][Outcome=Success][CMCRequest=MIG7BgkqhkiG9w0BBwGgga0EgaowgacwgZ4wgZsCAQEGCCsGAQUFBwcRMYGLMIGIMFYxFTATBgNVBAoMDFNFQ3VyZS1Ec09PTzEcMBoGA1UECwwTZ2thcG9vcl9SSENTXzc1X3NzbDEfMB0GA1UEAwwWQ0EgU2lnbmluZyBDZXJ0aWZpY2F0ZQIECGnKhAoBBgQMd29uZGVyZnVsZGF5DBdnZWV0aWthIHRlc3QgcmV2b2NhdGlvbjAAMAAwAA==] CMC request received
0.http-bio-25443-exec-3 - [15/Feb/2018:05:44:49 EST] [14] [6] [AuditEvent=CMC_RESPONSE_SENT][SubjectID=$Unidentified$][Outcome=Success][CMCResponse=MIIGPwYJKoZIhvcNAQcCoIIGMDCCBiwCAQMxDzANBglghkgBZQMEAgMFADA0BggrBgEFBQcMA6AoBCYwJDAeMBwCAQEGCCsGAQUFBwcZMQ0wCwIBAjADAgEBAgEHMAAwAKCCA+gwggPkMIICzKADAgECAgQM3QwgMA0GCSqGSIb3DQEBDQUAMFMxEjAQBgNVBAoMCVNFQ3VyZS1EczEcMBoGA1UECwwTZ2thcG9vcl9SSENTXzc1X3NzbDEfMB0GA1UEAwwWQ0EgU2lnbmluZyBDZXJ0aWZpY2F0ZTAeFw0xODAyMTExOTE4MjlaFw0zODAyMTExOTE4MjlaMFMxEjAQBgNVBAoMCVNFQ3VyZS1EczEcMBoGA1UECwwTZ2thcG9vcl9SSENTXzc1X3NzbDEfMB0GA1UEAwwWQ0EgU2lnbmluZyBDZXJ0aWZpY2F0ZTCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAJRuy2MpwSogHtg84aBToFzWzZmkqCdIlO363KqhGb9SDI7nYdJWfSuMW3sMpdxeP/E9DqaEgiTw1b3OBTxSojLHbcjzAiT4iRNv2kwZwMit7JmfemVWMHCwoGm80qrUwUoIcau/I86HXrGN6BjTzjHQJHMbefH+I2zqh0bXhcLCvfH/Vg4X39eQ1Fp/xtX2E8SvjgBagvFVMcUw9XCPk4Gn7i6TTY4fgqq7qqZqrsVNziA2NL07BqvX9joCI3RzJwnxzVP1r8fBA9sPLHrkYUxue/ObQo2uRL91OYdI3R4HLJilbrgYWrixziDXPr6UrbEsiEE+rSg4ff+0yBoGT78CAwEAAaOBvzCBvDAfBgNVHSMEGDAWgBRexDUJbLEkPOUGRug4ZhxMlYyjRjAPBgNVHRMBAf8EBTADAQH/MA4GA1UdDwEB/wQEAwIBxjAdBgNVHQ4EFgQUXsQ1CWyxJDzlBkboOGYcTJWMo0YwWQYIKwYBBQUHAQEETTBLMEkGCCsGAQUFBzABhj1odHRwOi8vY3NxYTQtZ3Vlc3QwNC5pZG0ubGFiLmVuZy5yZHUucmVkaGF0LmNvbToyNTA4MC9jYS9vY3NwMA0GCSqGSIb3DQEBDQUAA4IBAQBV+JNL9Gpm88yTiWPdJgHpiXVQusKJIchrRBTFA1ZbBTFJTcsjv5XrdvEGS4X5PcO6xzWxFLKiiS7T6LA0g6ghVubwqcHo3tmj+xHxNhVopwa9TxvXEPNwfnBFluUwRMoDy1ULb4/ohplmeGVkEeNLfTyo0xtpBSMj92iy6ZwYw5dmE0ZFxfx6hzUnk65qn8H2mIdnWHiRjkwQGCdrq2oizcVM0OaX5rz0msgqSWFO85XjX/IxPVJJNNixSgSFIirVLToModCqX2puWn4wermn8INI3k8MMPOxpEK6L6IFEfGUqXEr/YnRgAGrPljw39p2wU/SCnp8P8CVzIssi/x0MYIB8jCCAe4CAQEwWzBTMRIwEAYDVQQKDAlTRUN1cmUtRHMxHDAaBgNVBAsME2drYXBvb3JfUkhDU183NV9zc2wxHzAdBgNVBAMMFkNBIFNpZ25pbmcgQ2VydGlmaWNhdGUCBAzdDCAwDQYJYIZIAWUDBAIDBQCgajAXBgkqhkiG9w0BCQMxCgYIKwYBBQUHDAMwTwYJKoZIhvcNAQkEMUIEQEvv2Hre+zYecA1BQPgG1/2oiSly9W6NdK7+dN9RxLwLiAyPnTYH/6v+5z4bW4rdVvzS+N6RWR5fhCwr7OIr37EwDQYJKoZIhvcNAQENBQAEggEAK+9OkkkDSE+652cRCEQYBNwO6iLXbOGoVWas5ahTqvMLlSAYOTD8PVOrJvkTKcCyUQXMQc3SbGTurVFPL7o8PFwJ05jou0DmG3o4J6/Djbf+Gt0QVPW/tVwN4x49JrRB3LJXRv/EQU8EGn85/hYgcrLJMwUJzMnu5aeoilbotAItwzj6sFezHFCqTwu9aHWFYGlU07IAZJL/6LGX5q8V0iuU9eK92K2PuK3pH0Ya5KIWIWKg0igSgBZt6e4PkznU2ln7Am5hTrfM23EsvHOU7cBwIJHLVSotzj1fwkPO7rf7cOY1CCFjprjsJqj3qlhQN7WTpsPX1nPZkrmgVodYtg==] CMC response sent
0.http-bio-25443-exec-3 - [15/Feb/2018:05:44:49 EST] [14] [6] [AuditEvent=ACCESS_SESSION_TERMINATED][ClientIP=10.12.28.208][ServerIP=10.12.28.208][SubjectID=UID=sslauth,OU=People][Outcome=Success][Info=CLOSE_NOTIFY] access session terminated
Comment 6 Christina Fu 2018-02-15 18:30:19 UTC 
Again, whether subjectID contains anything meaningful or not depends on what type of authentication was used and whether at the point of the audit event the info is available or not.
Although looking at the events there in comment #5
[AuditEvent=ACCESS_SESSION_ESTABLISH][ClientIP=10.12.28.208][ServerIP=10.12.28.208][SubjectID=UID=sslauth,OU=People][Outcome=Success] access session establish success
The above event suggests that this was an SSL client authentication?

If so then I think the SubjectID should be carried throughout the rest of the operations.
Please include your test steps and config etc. when reporting issues so we don't have to guess. thanks.
Comment 7 Geetika Kapoor 2018-02-20 13:05:50 UTC 
Hi christina,

I am able to get the the behavior as mentioned in https://bugzilla.redhat.com/show_bug.cgi?id=1525306#c5 in below scenario.

Setup:
-----

1. I am trying to revoke a certificate.
2. I am using incorrect revRequest.sharedSecret=wonderfulday12345.
Correct value is revRequest.sharedSecret=wonderfulday.
3. In this case debug logs shows:

[20/Feb/2018:08:01:38][http-bio-25443-exec-11]: SharedSecret.decryptShrTokData: wrapped session key retrieved
[20/Feb/2018:08:01:38][http-bio-25443-exec-11]: SharedSecret.decryptShrTokData: wrapped passphrase retrieved
[20/Feb/2018:08:01:38][http-bio-25443-exec-11]: SharedSecret.getSharedToken(BigInteger serial): returning
[20/Feb/2018:08:01:38][http-bio-25443-exec-11]: CMCOutputTemplate: processRevokeRequestControl:  Client and server shared secret are not the same, cannot revoke certificate.
[20/Feb/2018:08:01:38][http-bio-25443-exec-11]: SignedAuditLogger: event CERT_STATUS_CHANGE_REQUEST_PROCESSED
[20/Feb/2018:08:01:38][http-bio-25443-exec-11]: LogFile: event type not selected: CERT_STATUS_CHANGE_REQUEST_PROCESSED


4. Audit logs :

0.http-bio-25443-exec-11 - [20/Feb/2018:08:01:38 EST] [14] [6] [AuditEvent=ACCESS_SESSION_ESTABLISH][ClientIP=10.12.28.208][ServerIP=10.12.28.208][SubjectID=UID=sslauth,OU=People][Outcome=Success] access session establish success
0.http-bio-25443-exec-11 - [20/Feb/2018:08:01:38 EST] [14] [6] [AuditEvent=AUTHZ][SubjectID=$Unidentified$][Outcome=Success][aclResource=certServer.ee.profile][Op=submit] authorization success
0.http-bio-25443-exec-11 - [20/Feb/2018:08:01:38 EST] [14] [6] [AuditEvent=CMC_REQUEST_RECEIVED][SubjectID=$Unidentified$][Outcome=Success][CMCRequest=MIG9BgkqhkiG9w0BBwGgga8EgawwgakwgaAwgZ0CAQEGCCsGAQUFBwcRMYGNMIGKMFMxEjAQBgNVBAoMCVNFQ3VyZS1EczEcMBoGA1UECwwTZ2thcG9vcl9SSENTXzc1X3NzbDEfMB0GA1UEAwwWQ0EgU2lnbmluZyBDZXJ0aWZpY2F0ZQIECGnKhAoBBgQRd29uZGVyZnVsZGF5MTIzNDUMF2dlZXRpa2EgdGVzdCByZXZvY2F0aW9uMAAwADAA] CMC request received
0.http-bio-25443-exec-11 - [20/Feb/2018:08:01:38 EST] [14] [6] [AuditEvent=CMC_RESPONSE_SENT][SubjectID=$Unidentified$][Outcome=Success][CMCResponse=MIIGPwYJKoZIhvcNAQcCoIIGMDCCBiwCAQMxDzANBglghkgBZQMEAgMFADA0BggrBgEFBQcMA6AoBCYwJDAeMBwCAQEGCCsGAQUFBwcZMQ0wCwIBAjADAgEBAgEHMAAwAKCCA+gwggPkMIICzKADAgECAgQM3QwgMA0GCSqGSIb3DQEBDQUAMFMxEjAQBgNVBAoMCVNFQ3VyZS1EczEcMBoGA1UECwwTZ2thcG9vcl9SSENTXzc1X3NzbDEfMB0GA1UEAwwWQ0EgU2lnbmluZyBDZXJ0aWZpY2F0ZTAeFw0xODAyMTExOTE4MjlaFw0zODAyMTExOTE4MjlaMFMxEjAQBgNVBAoMCVNFQ3VyZS1EczEcMBoGA1UECwwTZ2thcG9vcl9SSENTXzc1X3NzbDEfMB0GA1UEAwwWQ0EgU2lnbmluZyBDZXJ0aWZpY2F0ZTCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAJRuy2MpwSogHtg84aBToFzWzZmkqCdIlO363KqhGb9SDI7nYdJWfSuMW3sMpdxeP/E9DqaEgiTw1b3OBTxSojLHbcjzAiT4iRNv2kwZwMit7JmfemVWMHCwoGm80qrUwUoIcau/I86HXrGN6BjTzjHQJHMbefH+I2zqh0bXhcLCvfH/Vg4X39eQ1Fp/xtX2E8SvjgBagvFVMcUw9XCPk4Gn7i6TTY4fgqq7qqZqrsVNziA2NL07BqvX9joCI3RzJwnxzVP1r8fBA9sPLHrkYUxue/ObQo2uRL91OYdI3R4HLJilbrgYWrixziDXPr6UrbEsiEE+rSg4ff+0yBoGT78CAwEAAaOBvzCBvDAfBgNVHSMEGDAWgBRexDUJbLEkPOUGRug4ZhxMlYyjRjAPBgNVHRMBAf8EBTADAQH/MA4GA1UdDwEB/wQEAwIBxjAdBgNVHQ4EFgQUXsQ1CWyxJDzlBkboOGYcTJWMo0YwWQYIKwYBBQUHAQEETTBLMEkGCCsGAQUFBzABhj1odHRwOi8vY3NxYTQtZ3Vlc3QwNC5pZG0ubGFiLmVuZy5yZHUucmVkaGF0LmNvbToyNTA4MC9jYS9vY3NwMA0GCSqGSIb3DQEBDQUAA4IBAQBV+JNL9Gpm88yTiWPdJgHpiXVQusKJIchrRBTFA1ZbBTFJTcsjv5XrdvEGS4X5PcO6xzWxFLKiiS7T6LA0g6ghVubwqcHo3tmj+xHxNhVopwa9TxvXEPNwfnBFluUwRMoDy1ULb4/ohplmeGVkEeNLfTyo0xtpBSMj92iy6ZwYw5dmE0ZFxfx6hzUnk65qn8H2mIdnWHiRjkwQGCdrq2oizcVM0OaX5rz0msgqSWFO85XjX/IxPVJJNNixSgSFIirVLToModCqX2puWn4wermn8INI3k8MMPOxpEK6L6IFEfGUqXEr/YnRgAGrPljw39p2wU/SCnp8P8CVzIssi/x0MYIB8jCCAe4CAQEwWzBTMRIwEAYDVQQKDAlTRUN1cmUtRHMxHDAaBgNVBAsME2drYXBvb3JfUkhDU183NV9zc2wxHzAdBgNVBAMMFkNBIFNpZ25pbmcgQ2VydGlmaWNhdGUCBAzdDCAwDQYJYIZIAWUDBAIDBQCgajAXBgkqhkiG9w0BCQMxCgYIKwYBBQUHDAMwTwYJKoZIhvcNAQkEMUIEQEvv2Hre+zYecA1BQPgG1/2oiSly9W6NdK7+dN9RxLwLiAyPnTYH/6v+5z4bW4rdVvzS+N6RWR5fhCwr7OIr37EwDQYJKoZIhvcNAQENBQAEggEAK+9OkkkDSE+652cRCEQYBNwO6iLXbOGoVWas5ahTqvMLlSAYOTD8PVOrJvkTKcCyUQXMQc3SbGTurVFPL7o8PFwJ05jou0DmG3o4J6/Djbf+Gt0QVPW/tVwN4x49JrRB3LJXRv/EQU8EGn85/hYgcrLJMwUJzMnu5aeoilbotAItwzj6sFezHFCqTwu9aHWFYGlU07IAZJL/6LGX5q8V0iuU9eK92K2PuK3pH0Ya5KIWIWKg0igSgBZt6e4PkznU2ln7Am5hTrfM23EsvHOU7cBwIJHLVSotzj1fwkPO7rf7cOY1CCFjprjsJqj3qlhQN7WTpsPX1nPZkrmgVodYtg==] CMC response sent
0.http-bio-25443-exec-11 - [20/Feb/2018:08:01:38 EST] [14] [6] [AuditEvent=ACCESS_SESSION_TERMINATED][ClientIP=10.12.28.208][ServerIP=10.12.28.208][SubjectID=UID=sslauth,OU=People][Outcome=Success][Info=CLOSE_NOTIFY] access session terminated
Comment 8 Geetika Kapoor 2018-02-20 13:14:53 UTC 
Sorry I missed to  reply for your question, ssl auth is successful because certificate used is correct in HttpClient.
Comment 9 Christina Fu 2018-02-22 23:25:20 UTC 
The client failed the shared secret check so we cannot identify the client.
So as far as this bug goes, the CMC_REQUEST_RECEIVED and CMC_RESPONSE_SENT look correct.

There should be a "CMC_PROOF_OF_IDENTIFICATION" event to record the attempted credential though.  If that's missing then it's a bug.  But it's a different bug. Are you sure CMC_PROOF_OF_IDENTIFICATION not in your audit log when shared token failed?
Comment 10 Geetika Kapoor 2018-02-23 06:02:45 UTC 
Hi Christina,

I didn't find that event neither in audit logs nor debug logs. Here is the snip:

I re-run the test again:

debug logs:
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: EnrollProfile: parseCMC: pre-signed CMC request; no further proof of identification check
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: EnrollProfile: parseCMC: found numOfOtherMsgs: 0
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: EnrollProfile: parseCMC: getting :cmc.popLinkWitnessRequired
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: EnrollProfile: parseCMC: popLinkWitness(V2) not required
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: EnrollProfile: parseCMC: nummsgs 0; returning...
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: EnrollProfile: createRequests: parseCMC returns cmc_msgs null
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: ProfileSubmitCMCServlet: revocation request
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: ProfileSubmitCMCServlet: done serving
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMCOutputTemplate: createFullResponse: begins with cert_request_type=cmc
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMCOutputTemplate: createFullResponse:  processing cmc
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMCOutputTemplate: createFullResponse:  reqs null. could be revocation
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMCOutputTemplate: createFullResponse:  processing controls
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMCOutputTemplate: processRevokeRequestControl: begins
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMCOutputTemplate: processRevokeRequestControl: authManagerId =CMCUserSignedAuth
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMCOutputTemplate: processRevokeRequestControl: checking shared secret
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: In LdapBoundConnFactory::getConn()
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: masterConn is connected: true
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: getConn: conn is connected true
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: getConn: mNumConns now 2
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: returnConn: mNumConns now 3
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: SharedSecret.decryptShrTokData: wrapped session key retrieved
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: SharedSecret.decryptShrTokData: wrapped passphrase retrieved
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: SharedSecret.getSharedToken(BigInteger serial): returning
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMCOutputTemplate: processRevokeRequestControl:  Client and server shared secret are not the same, cannot revoke certificate.
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: SignedAuditLogger: event CERT_STATUS_CHANGE_REQUEST_PROCESSED
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: LogFile: event type not selected: CERT_STATUS_CHANGE_REQUEST_PROCESSED
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMCOutputTemplate: createFullResponse:  after new ResponseBody, respBody not null
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMCOutputTemplate: getContentInfo: begins
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMCOutputTemplate: getContentInfo:  - done
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: SignedAuditLogger: event CMC_RESPONSE_SENT
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMCOutputTemplate: createFullResponse: ends
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: CMSServlet: curDate=Fri Feb 23 00:19:55 EST 2018 id=caProfileSubmitUserSignedCMCFull time=196
[23/Feb/2018:00:19:55][http-bio-25443-exec-1]: SignedAuditLogger: event ACCESS_SESSION_TERMINATED

Audit logs:

0.http-bio-25443-exec-1 - [23/Feb/2018:00:19:54 EST] [14] [6] [AuditEvent=ACCESS_SESSION_ESTABLISH][ClientIP=10.12.28.208][ServerIP=10.12.28.208][SubjectID=CN=Certecc,UID=Testing][Outcome=Success] access session establish success
0.http-bio-25443-exec-1 - [23/Feb/2018:00:19:55 EST] [14] [6] [AuditEvent=AUTHZ][SubjectID=$Unidentified$][Outcome=Success][aclResource=certServer.ee.profile][Op=submit] authorization success
0.http-bio-25443-exec-1 - [23/Feb/2018:00:19:55 EST] [14] [6] [AuditEvent=CMC_REQUEST_RECEIVED][SubjectID=$Unidentified$][Outcome=Success][CMCRequest=MIG9BgkqhkiG9w0BBwGgga8EgawwgakwgaAwgZ0CAQEGCCsGAQUFBwcRMYGNMIGKMFMxEjAQBgNVBAoMCVNFQ3VyZS1EczEcMBoGA1UECwwTZ2thcG9vcl9SSENTXzc1X3NzbDEfMB0GA1UEAwwWQ0EgU2lnbmluZyBDZXJ0aWZpY2F0ZQIECGnKhAoBBgQRd29uZGVyZnVsZGF5MTIzNDUMF2dlZXRpa2EgdGVzdCByZXZvY2F0aW9uMAAwADAA] CMC request received
0.http-bio-25443-exec-1 - [23/Feb/2018:00:19:55 EST] [14] [6] [AuditEvent=CMC_RESPONSE_SENT][SubjectID=$Unidentified$][Outcome=Success][CMCResponse=MIIGPwYJKoZIhvcNAQcCoIIGMDCCBiwCAQMxDzANBglghkgBZQMEAgMFADA0BggrBgEFBQcMA6AoBCYwJDAeMBwCAQEGCCsGAQUFBwcZMQ0wCwIBAjADAgEBAgEHMAAwAKCCA+gwggPkMIICzKADAgECAgQM3QwgMA0GCSqGSIb3DQEBDQUAMFMxEjAQBgNVBAoMCVNFQ3VyZS1EczEcMBoGA1UECwwTZ2thcG9vcl9SSENTXzc1X3NzbDEfMB0GA1UEAwwWQ0EgU2lnbmluZyBDZXJ0aWZpY2F0ZTAeFw0xODAyMTExOTE4MjlaFw0zODAyMTExOTE4MjlaMFMxEjAQBgNVBAoMCVNFQ3VyZS1EczEcMBoGA1UECwwTZ2thcG9vcl9SSENTXzc1X3NzbDEfMB0GA1UEAwwWQ0EgU2lnbmluZyBDZXJ0aWZpY2F0ZTCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAJRuy2MpwSogHtg84aBToFzWzZmkqCdIlO363KqhGb9SDI7nYdJWfSuMW3sMpdxeP/E9DqaEgiTw1b3OBTxSojLHbcjzAiT4iRNv2kwZwMit7JmfemVWMHCwoGm80qrUwUoIcau/I86HXrGN6BjTzjHQJHMbefH+I2zqh0bXhcLCvfH/Vg4X39eQ1Fp/xtX2E8SvjgBagvFVMcUw9XCPk4Gn7i6TTY4fgqq7qqZqrsVNziA2NL07BqvX9joCI3RzJwnxzVP1r8fBA9sPLHrkYUxue/ObQo2uRL91OYdI3R4HLJilbrgYWrixziDXPr6UrbEsiEE+rSg4ff+0yBoGT78CAwEAAaOBvzCBvDAfBgNVHSMEGDAWgBRexDUJbLEkPOUGRug4ZhxMlYyjRjAPBgNVHRMBAf8EBTADAQH/MA4GA1UdDwEB/wQEAwIBxjAdBgNVHQ4EFgQUXsQ1CWyxJDzlBkboOGYcTJWMo0YwWQYIKwYBBQUHAQEETTBLMEkGCCsGAQUFBzABhj1odHRwOi8vY3NxYTQtZ3Vlc3QwNC5pZG0ubGFiLmVuZy5yZHUucmVkaGF0LmNvbToyNTA4MC9jYS9vY3NwMA0GCSqGSIb3DQEBDQUAA4IBAQBV+JNL9Gpm88yTiWPdJgHpiXVQusKJIchrRBTFA1ZbBTFJTcsjv5XrdvEGS4X5PcO6xzWxFLKiiS7T6LA0g6ghVubwqcHo3tmj+xHxNhVopwa9TxvXEPNwfnBFluUwRMoDy1ULb4/ohplmeGVkEeNLfTyo0xtpBSMj92iy6ZwYw5dmE0ZFxfx6hzUnk65qn8H2mIdnWHiRjkwQGCdrq2oizcVM0OaX5rz0msgqSWFO85XjX/IxPVJJNNixSgSFIirVLToModCqX2puWn4wermn8INI3k8MMPOxpEK6L6IFEfGUqXEr/YnRgAGrPljw39p2wU/SCnp8P8CVzIssi/x0MYIB8jCCAe4CAQEwWzBTMRIwEAYDVQQKDAlTRUN1cmUtRHMxHDAaBgNVBAsME2drYXBvb3JfUkhDU183NV9zc2wxHzAdBgNVBAMMFkNBIFNpZ25pbmcgQ2VydGlmaWNhdGUCBAzdDCAwDQYJYIZIAWUDBAIDBQCgajAXBgkqhkiG9w0BCQMxCgYIKwYBBQUHDAMwTwYJKoZIhvcNAQkEMUIEQEvv2Hre+zYecA1BQPgG1/2oiSly9W6NdK7+dN9RxLwLiAyPnTYH/6v+5z4bW4rdVvzS+N6RWR5fhCwr7OIr37EwDQYJKoZIhvcNAQENBQAEggEAK+9OkkkDSE+652cRCEQYBNwO6iLXbOGoVWas5ahTqvMLlSAYOTD8PVOrJvkTKcCyUQXMQc3SbGTurVFPL7o8PFwJ05jou0DmG3o4J6/Djbf+Gt0QVPW/tVwN4x49JrRB3LJXRv/EQU8EGn85/hYgcrLJMwUJzMnu5aeoilbotAItwzj6sFezHFCqTwu9aHWFYGlU07IAZJL/6LGX5q8V0iuU9eK92K2PuK3pH0Ya5KIWIWKg0igSgBZt6e4PkznU2ln7Am5hTrfM23EsvHOU7cBwIJHLVSotzj1fwkPO7rf7cOY1CCFjprjsJqj3qlhQN7WTpsPX1nPZkrmgVodYtg==] CMC response sent
0.http-bio-25443-exec-1 - [23/Feb/2018:00:19:55 EST] [14] [6] [AuditEvent=ACCESS_SESSION_TERMINATED][ClientIP=10.12.28.208][ServerIP=10.12.28.208][SubjectID=CN=Certecc,UID=Testing][Outcome=Success][Info=CLOSE_NOTIFY] access session terminated

Step 2: I try to verify event "CMC_PROOF_OF_IDENTIFICATION" in debug and audit logs.If you check the logs i saw that event CMC_PROOF_OF_IDENTIFICATION last time on 12 Feb. After that i re-run this test many times but it never occur.

[root@csqa4-guest04 ca]# grep "CMC_PROOF_OF_IDENTIFICATION" debug
[11/Feb/2018:14:51:46][http-bio-25080-exec-4]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[11/Feb/2018:14:51:46][http-bio-25080-exec-4]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION
[11/Feb/2018:14:53:58][http-bio-25080-exec-1]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[11/Feb/2018:14:53:58][http-bio-25080-exec-1]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION
[11/Feb/2018:14:55:27][http-bio-25080-exec-2]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[11/Feb/2018:14:55:27][http-bio-25080-exec-2]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION
[11/Feb/2018:14:58:39][http-bio-25080-exec-1]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[11/Feb/2018:14:58:39][http-bio-25080-exec-1]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION
[11/Feb/2018:15:02:03][http-bio-25080-exec-1]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[11/Feb/2018:15:02:03][http-bio-25080-exec-1]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION
[11/Feb/2018:15:03:00][http-bio-25080-exec-2]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[11/Feb/2018:15:03:00][http-bio-25080-exec-2]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION
[12/Feb/2018:01:57:43][http-bio-25080-exec-7]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[12/Feb/2018:01:57:43][http-bio-25080-exec-7]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION
[12/Feb/2018:02:20:15][http-bio-25080-exec-8]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[12/Feb/2018:02:20:15][http-bio-25080-exec-8]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION
[12/Feb/2018:02:27:45][http-bio-25080-exec-9]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[12/Feb/2018:02:27:45][http-bio-25080-exec-9]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION
[12/Feb/2018:02:44:34][http-bio-25080-exec-1]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[12/Feb/2018:02:44:34][http-bio-25080-exec-1]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION
[12/Feb/2018:03:06:20][http-bio-25080-exec-2]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[12/Feb/2018:03:06:20][http-bio-25080-exec-2]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION
[12/Feb/2018:04:46:39][http-bio-25080-exec-3]: SignedAuditLogger: event CMC_PROOF_OF_IDENTIFICATION
[12/Feb/2018:04:46:39][http-bio-25080-exec-3]: LogFile: event type not selected: CMC_PROOF_OF_IDENTIFICATION

[root@csqa4-guest04 ca]# grep "CMC_PROOF_OF_IDENTIFICATION" signedAudit/*
[root@csqa4-guest04 ca]#

 Step 3: I check the CS.cfg to check for the event.
CS.cfg:
log.instance.SignedAudit.events=ACCESS_SESSION_ESTABLISH,ACCESS_SESSION_TERMINATED,AUTH,AUTHZ,CERT_REQUEST_PROCESSED,CERT_SIGNING_INFO,CMC_SIGNED_REQUEST_SIG_VERIFY,CMC_USER_SIGNED_REQUEST_SIG_VERIFY,CMC_REQUEST_RECEIVED,CMC_RESPONSE_SENT,CONFIG_AUTH,CONFIG_CERT_PROFILE,CONFIG_ENCRYPTION,CONFIG_ROLE,CONFIG_SERIAL_NUMBER,CONFIG_SIGNED_AUDIT,CONFIG_TRUSTED_PUBLIC_KEY,CRL_SIGNING_INFO,DELTA_CRL_GENERATION,FULL_CRL_GENERATION,LOG_PATH_CHANGE,OCSP_GENERATION,OCSP_SIGNING_INFO,PROFILE_CERT_REQUEST,PROOF_OF_POSSESSION,RANDOM_GENERATION,ROLE_ASSUME,SECURITY_DOMAIN_UPDATE,SELFTESTS_EXECUTION

[root@csqa4-guest04 ca]# grep -i "CMC_PROOF_OF_IDENTIFICATION" /etc/pki/gkapoor_RHCS_75_ssl/ca/CS.cfg
log.instance.SignedAudit._005=## AUDIT_LOG_STARTUP,AUDIT_LOG_SHUTDOWN,ROLE_ASSUME,CONFIG_CERT_POLICY,CONFIG_CERT_PROFILE,CONFIG_CRL_PROFILE,CONFIG_OCSP_PROFILE,CONFIG_AUTH,CONFIG_ROLE,CONFIG_ACL,CONFIG_SIGNED_AUDIT,CONFIG_ENCRYPTION,CONFIG_TRUSTED_PUBLIC_KEY,CONFIG_DRM,SELFTESTS_EXECUTION,AUDIT_LOG_DELETE,LOG_PATH_CHANGE,LOG_EXPIRATION_CHANGE,PRIVATE_KEY_ARCHIVE_REQUEST,PRIVATE_KEY_ARCHIVE_REQUEST_PROCESSED,PRIVATE_KEY_EXPORT_REQUEST_PROCESSED_SUCCESS,PRIVATE_KEY_EXPORT_REQUEST_PROCESSED_FAILURE,KEY_RECOVERY_REQUEST,KEY_RECOVERY_REQUEST_ASYNC,KEY_RECOVERY_AGENT_LOGIN,KEY_RECOVERY_REQUEST_PROCESSED,KEY_RECOVERY_REQUEST_PROCESSED_ASYNC,KEY_GEN_ASYMMETRIC,CERT_SIGNING_INFO,OCSP_SIGNING_INFO,CRL_SIGNING_INFO,NON_PROFILE_CERT_REQUEST,PROFILE_CERT_REQUEST,CERT_REQUEST_PROCESSED,CERT_STATUS_CHANGE_REQUEST,CERT_STATUS_CHANGE_REQUEST_PROCESSED,AUTHZ,INTER_BOUNDARY,AUTH,CERT_PROFILE_APPROVAL,PROOF_OF_POSSESSION,CMC_PROOF_OF_IDENTIFICATION,CMC_ID_POP_LINK_WITNESS,SCHEDULE_CRL_GENERATION,DELTA_CRL_GENERATION,DELTA_CRL_PUBLISHING,FULL_CRL_GENERATION,FULL_CRL_PUBLISHING,CRL_RETRIEVAL,CRL_VALIDATION,CMC_SIGNED_REQUEST_SIG_VERIFY,CMC_USER_SIGNED_REQUEST_SIG_VERIFY,CMC_REQUEST_RECEIVED,CMC_RESPONSE_SENT,SERVER_SIDE_KEYGEN_REQUEST_PROCESSED_FAILURE,SERVER_SIDE_KEYGEN_REQUEST_PROCESSED_SUCCESS,SERVER_SIDE_KEYGEN_REQUEST,COMPUTE_SESSION_KEY_REQUEST,COMPUTE_SESSION_KEY_REQUEST_PROCESSED_SUCCESS, COMPUTE_SESSION_KEY_REQUEST_PROCESSED_FAILURE,DIVERSIFY_KEY_REQUEST,DIVERSIFY_KEY_REQUEST_PROCESSED_SUCCESS, DIVERSIFY_KEY_REQUEST_PROCESSED_FAILURE,ENCRYPT_DATA_REQUEST,ENCRYPT_DATA_REQUEST_PROCESSED_SUCCESS,ENCRYPT_DATA_REQUEST_PROCESSED_FAILURE,OCSP_GENERATION,COMPUTE_RANDOM_DATA_REQUEST,COMPUTE_RANDOM_DATA_REQUEST_PROCESSED_SUCCESS,COMPUTE_RANDOM_DATA_REQUEST_PROCESSED_FAILURE,CIMC_CERT_VERIFICATION,SECURITY_DOMAIN_UPDATE,CONFIG_SERIAL_NUMBER,AUTHORITY_CONFIG,ACCESS_SESSION_ESTABLISH,ACCESS_SESSION_TERMINATED,SECURITY_DATA_ARCHIVAL_REQUEST,RANDOM_GENERATION
Comment 11 Christina Fu 2018-02-23 17:21:53 UTC 
ok it looks like we didn't enable AuditEvent=CMC_PROOF_OF_IDENTIFICATION by default.  As it would then supposed to record the attempted subject.
Could you enable it and see if it indeed does that?

Maybe I can enable it at the next CMC bug that I work on.

But as far as this bug goes, I think it looks good.
Comment 12 Geetika Kapoor 2018-02-23 18:20:15 UTC 
I think we can move this bug to verified. 
I can add Above mentioned details in https://bugzilla.redhat.com/show_bug.cgi?id=1540440.

I have added "CMC_PROOF_OF_IDENTIFICATION" in log.instance.SignedAudit.events in CS.cfg and restart the instance.

log.instance.SignedAudit.events=ACCESS_SESSION_ESTABLISH,ACCESS_SESSION_TERMINATED,AUTH,AUTHZ,CERT_REQUEST_PROCESSED,CERT_SIGNING_INFO,CMC_SIGNED_REQUEST_SIG_VERIFY,CMC_USER_SIGNED_REQUEST_SIG_VERIFY,CMC_REQUEST_RECEIVED,CMC_RESPONSE_SENT,CONFIG_AUTH,CONFIG_CERT_PROFILE,CONFIG_ENCRYPTION,CONFIG_ROLE,CONFIG_SERIAL_NUMBER,CONFIG_SIGNED_AUDIT,CONFIG_TRUSTED_PUBLIC_KEY,CRL_SIGNING_INFO,DELTA_CRL_GENERATION,FULL_CRL_GENERATION,LOG_PATH_CHANGE,OCSP_GENERATION,OCSP_SIGNING_INFO,PROFILE_CERT_REQUEST,PROOF_OF_POSSESSION,RANDOM_GENERATION,ROLE_ASSUME,SECURITY_DOMAIN_UPDATE,SELFTESTS_EXECUTION,CMC_PROOF_OF_IDENTIFICATION


I couldn't find "CMC_PROOF_OF_IDENTIFICATION" in audit or debug logs.
Comment 13 Geetika Kapoor 2018-02-23 20:16:46 UTC 
Marking This bug "Verified" and adding all the observed behavior and issues in https://bugzilla.redhat.com/show_bug.cgi?id=1540440.
Comment 15 errata-xmlrpc 2018-04-10 17:02:54 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/RHBA-2018:0925