Fix auditing in retrieveKey

The auditing in retrieveKey is all messed up.
* Added new audit event to track accesses to KeyInfo queries.
  They may produce a lot of events, especially if events are
  generated for every listing of data.  By default, this event
  may be turned off.
* Added audit events for generation and processing of key
  recovery requests.

Change-Id: Icb695e712bdfadf0a80903aa52bd00b9d4883182

4 files changed, 132 insertions, 19 deletions

diff --git a/base/common/src/com/netscape/certsrv/logging/event/SecurityDataInfoEvent.java b/base/common/src/com/netscape/certsrv/logging/event/SecurityDataInfoEvent.java
new file mode 100644
index 000000000..82c049e3b
--- /dev/null
+++ b/base/common/src/com/netscape/certsrv/logging/event/SecurityDataInfoEvent.java
@@ -0,0 +1,49 @@
+// --- BEGIN COPYRIGHT BLOCK ---
+// This program is free software; you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation; version 2 of the License.
+//
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+// GNU General Public License for more details.
+//
+// You should have received a copy of the GNU General Public License along
+// with this program; if not, write to the Free Software Foundation, Inc.,
+// 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
+//
+// (C) 2017 Red Hat, Inc.
+// All rights reserved.
+// --- END COPYRIGHT BLOCK ---
+package com.netscape.certsrv.logging.event;
+
+import com.netscape.certsrv.dbs.keydb.KeyId;
+import com.netscape.certsrv.logging.AuditEvent;
+
+public class SecurityDataInfoEvent extends AuditEvent {
+
+    private static final long serialVersionUID = 1L;
+
+    private static final String LOGGING_PROPERTY =
+            "LOGGING_SIGNED_AUDIT_SECURITY_DATA_INFO";
+
+    public SecurityDataInfoEvent(
+            String subjectID,
+            String outcome,
+            KeyId keyID,
+            String clientKeyID,
+            String failureReason,
+            String pubKey) {
+
+        super(LOGGING_PROPERTY);
+
+        setParameters(new Object[] {
+                subjectID,
+                outcome,
+                keyID,
+                clientKeyID,
+                failureReason,
+                pubKey
+        });
+    }
+}
\ No newline at end of file
diff --git a/base/kra/shared/conf/CS.cfg b/base/kra/shared/conf/CS.cfg
index 298e35ac9..4b6ff747c 100644
--- a/base/kra/shared/conf/CS.cfg
+++ b/base/kra/shared/conf/CS.cfg
@@ -300,7 +300,7 @@ log.instance.SignedAudit._001=## Signed Audit Logging
 log.instance.SignedAudit._002=##
 log.instance.SignedAudit._003=##
 log.instance.SignedAudit._004=## Available Audit events:
-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,KEY_RECOVERY_AGENT_LOGIN,KEY_GEN_ASYMMETRIC,NON_PROFILE_CERT_REQUEST,PROFILE_CERT_REQUEST,CERT_REQUEST_PROCESSED,CERT_STATUS_CHANGE_REQUEST,CERT_STATUS_CHANGE_REQUEST_PROCESSED,AUTHZ_SUCCESS,AUTHZ_FAIL,INTER_BOUNDARY,AUTH_FAIL,AUTH_SUCCESS,CERT_PROFILE_APPROVAL,PROOF_OF_POSSESSION,CRL_RETRIEVAL,CRL_VALIDATION,CMC_SIGNED_REQUEST_SIG_VERIFY,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_ADD_CA_REQUEST,OCSP_ADD_CA_REQUEST_PROCESSED,OCSP_REMOVE_CA_REQUEST,OCSP_REMOVE_CA_REQUEST_PROCESSED_SUCCESS,OCSP_REMOVE_CA_REQUEST_PROCESSED_FAILURE,COMPUTE_RANDOM_DATA_REQUEST,COMPUTE_RANDOM_DATA_REQUEST_PROCESSED_SUCCESS,COMPUTE_RANDOM_DATA_REQUEST_PROCESSED_FAILURE,CIMC_CERT_VERIFICATION,CONFIG_SERIAL_NUMBER,SECURITY_DATA_ARCHIVAL_REQUEST,SECURITY_DATA_ARCHIVAL_REQUEST_PROCESSED,SECURITY_DATA_RECOVERY_REQUEST,SECURITY_DATA_RECOVERY_REQUEST_PROCESSED,SECURITY_DATA_RECOVERY_REQUEST_STATE_CHANGE,SECURITY_DATA_EXPORT_KEY,SYMKEY_GENERATION_REQUEST,SYMKEY_GENERATION_REQUEST_PROCESSED,ASYMKEY_GENERATION_REQUEST,ASYMKEY_GENERATION_REQUEST_PROCESSED,KEY_STATUS_CHANGE,ACCESS_SESSION_ESTABLISH_FAILURE,ACCESS_SESSION_ESTABLISH_SUCCESS,ACCESS_SESSION_TERMINATED
+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,KEY_RECOVERY_AGENT_LOGIN,KEY_GEN_ASYMMETRIC,NON_PROFILE_CERT_REQUEST,PROFILE_CERT_REQUEST,CERT_REQUEST_PROCESSED,CERT_STATUS_CHANGE_REQUEST,CERT_STATUS_CHANGE_REQUEST_PROCESSED,AUTHZ_SUCCESS,AUTHZ_FAIL,INTER_BOUNDARY,AUTH_FAIL,AUTH_SUCCESS,CERT_PROFILE_APPROVAL,PROOF_OF_POSSESSION,CRL_RETRIEVAL,CRL_VALIDATION,CMC_SIGNED_REQUEST_SIG_VERIFY,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_ADD_CA_REQUEST,OCSP_ADD_CA_REQUEST_PROCESSED,OCSP_REMOVE_CA_REQUEST,OCSP_REMOVE_CA_REQUEST_PROCESSED_SUCCESS,OCSP_REMOVE_CA_REQUEST_PROCESSED_FAILURE,COMPUTE_RANDOM_DATA_REQUEST,COMPUTE_RANDOM_DATA_REQUEST_PROCESSED_SUCCESS,COMPUTE_RANDOM_DATA_REQUEST_PROCESSED_FAILURE,CIMC_CERT_VERIFICATION,CONFIG_SERIAL_NUMBER,SECURITY_DATA_ARCHIVAL_REQUEST,SECURITY_DATA_ARCHIVAL_REQUEST_PROCESSED,SECURITY_DATA_RECOVERY_REQUEST,SECURITY_DATA_RECOVERY_REQUEST_PROCESSED,SECURITY_DATA_RECOVERY_REQUEST_STATE_CHANGE,SECURITY_DATA_EXPORT_KEY,SYMKEY_GENERATION_REQUEST,SYMKEY_GENERATION_REQUEST_PROCESSED,ASYMKEY_GENERATION_REQUEST,ASYMKEY_GENERATION_REQUEST_PROCESSED,KEY_STATUS_CHANGE,ACCESS_SESSION_ESTABLISH_FAILURE,ACCESS_SESSION_ESTABLISH_SUCCESS,ACCESS_SESSION_TERMINATED,SECURITY_DATA_INFO
 log.instance.SignedAudit._006=##
 log.instance.SignedAudit.bufferSize=512
 log.instance.SignedAudit.enable=true
diff --git a/base/kra/src/org/dogtagpki/server/kra/rest/KeyService.java b/base/kra/src/org/dogtagpki/server/kra/rest/KeyService.java
index 87e6f15d8..52799e67f 100644
--- a/base/kra/src/org/dogtagpki/server/kra/rest/KeyService.java
+++ b/base/kra/src/org/dogtagpki/server/kra/rest/KeyService.java
@@ -63,6 +63,9 @@ import com.netscape.certsrv.kra.IKeyService;
 import com.netscape.certsrv.logging.AuditEvent;
 import com.netscape.certsrv.logging.ILogger;
 import com.netscape.certsrv.logging.event.SecurityDataExportEvent;
+import com.netscape.certsrv.logging.event.SecurityDataInfoEvent;
+import com.netscape.certsrv.logging.event.SecurityDataRecoveryEvent;
+import com.netscape.certsrv.logging.event.SecurityDataRecoveryProcessedEvent;
 import com.netscape.certsrv.request.IRequest;
 import com.netscape.certsrv.request.IRequestQueue;
 import com.netscape.certsrv.request.RequestId;
@@ -92,6 +95,7 @@ public class KeyService extends SubsystemService implements KeyResource {
     private RequestId requestId;
     private KeyId keyId;
     private String auditInfo;
+    private String approvers;
 
     public KeyService() {
         kra = ( IKeyRecoveryAuthority ) CMS.getSubsystem( "kra" );
@@ -112,12 +116,14 @@ public class KeyService extends SubsystemService implements KeyResource {
     @Override
     public Response retrieveKey(KeyRecoveryRequest data) {
         try {
-            return retrieveKeyImpl(data);
+            Response response = retrieveKeyImpl(data);
+            auditRetrieveKey(ILogger.SUCCESS);
+            return response;
         } catch(RuntimeException e) {
-            auditError(e.getMessage());
+            auditRetrieveKeyError(e.getMessage());
             throw e;
         } catch (Exception e) {
-            auditError(e.getMessage());
+            auditRetrieveKeyError(e.getMessage());
             throw new PKIException(e.getMessage(), e);
         }
     }
@@ -191,17 +197,20 @@ public class KeyService extends SubsystemService implements KeyResource {
                 try {
                     queue.updateRequest(request);
                 } catch (EBaseException e) {
+                    auditRecoveryRequest(ILogger.FAILURE);
                     e.printStackTrace();
                     throw new PKIException(e.getMessage(), e);
                 }
 
                 CMS.debug("Returning created recovery request");
-                auditRetrieveKey(ILogger.SUCCESS, "Created recovery request");
+                auditRecoveryRequest(ILogger.SUCCESS);
 
                 KeyData keyData = new KeyData();
                 keyData.setRequestID(requestId);
                 return createOKResponse(keyData);
             }
+
+            auditRecoveryRequest(ILogger.SUCCESS);
         }
 
         data.setRequestId(requestId);
@@ -226,15 +235,19 @@ public class KeyService extends SubsystemService implements KeyResource {
                     throw new BadRequestException("Invalid request type: " + type);
             }
         } catch (Exception e) {
+            auditRecoveryRequestProcessed(ILogger.FAILURE, e.getMessage());
             throw new PKIException(e.getMessage(), e);
         }
 
         if (keyData == null) {
+            auditRecoveryRequestProcessed(ILogger.FAILURE, "No key record");
             throw new HTTPGoneException("No key record.");
         }
 
+        approvers = request.getExtDataInString(IRequest.ATTR_APPROVE_AGENTS);
+        auditRecoveryRequestProcessed(ILogger.SUCCESS, null);
+
         CMS.debug("KeyService: key retrieved");
-        auditRetrieveKey(ILogger.SUCCESS);
         return createOKResponse(keyData);
     }
 
@@ -408,10 +421,8 @@ public class KeyService extends SubsystemService implements KeyResource {
         try {
             return createOKResponse(listKeyInfos(clientKeyID, status, maxResults, maxTime, start, size, realm));
         } catch (RuntimeException e) {
-            auditError(e.getMessage());
             throw e;
         } catch (Exception e) {
-            auditError(e.getMessage());
             throw new PKIException(e.getMessage(), e);
         }
     }
@@ -449,7 +460,6 @@ public class KeyService extends SubsystemService implements KeyResource {
         try {
             Enumeration<IKeyRecord> e = repo.searchKeys(filter, maxResults, maxTime);
             if (e == null) {
-                auditRetrieveKey(ILogger.SUCCESS);
                 return infos;
             }
 
@@ -458,7 +468,11 @@ public class KeyService extends SubsystemService implements KeyResource {
             while (e.hasMoreElements()) {
                 IKeyRecord rec = e.nextElement();
                 if (rec == null) continue;
-                results.add(createKeyDataInfo(rec, false));
+
+                KeyInfo info = createKeyDataInfo(rec, false);
+                results.add(info);
+
+                auditKeyInfoSuccess(info.getKeyId(), null);
             }
 
             int total = results.size();
@@ -482,7 +496,6 @@ public class KeyService extends SubsystemService implements KeyResource {
         } catch (EBaseException e) {
             throw new PKIException(e.getMessage(), e);
         }
-        auditRetrieveKey(ILogger.SUCCESS);
 
         return infos;
     }
@@ -492,10 +505,10 @@ public class KeyService extends SubsystemService implements KeyResource {
         try {
             return getActiveKeyInfoImpl(clientKeyID);
         } catch (RuntimeException e) {
-            auditError(e.getMessage());
+            auditKeyInfoError(null, clientKeyID, e.getMessage());
             throw e;
         } catch (Exception e) {
-            auditError(e.getMessage());
+            auditKeyInfoError(null, clientKeyID, e.getMessage());
             throw new PKIException(e.getMessage(), e);
         }
     }
@@ -531,7 +544,7 @@ public class KeyService extends SubsystemService implements KeyResource {
                     throw new PKIException(e.toString(), e);
                 }
 
-                auditRetrieveKey(ILogger.SUCCESS);
+                auditKeyInfoSuccess(info.getKeyId(), clientKeyID);
 
                 return createOKResponse(info);
             }
@@ -616,11 +629,31 @@ public class KeyService extends SubsystemService implements KeyResource {
         auditRetrieveKey(status, null);
     }
 
-    public void auditError(String message) {
+    public void auditRetrieveKeyError(String message) {
         CMS.debug(message);
         auditRetrieveKey(ILogger.FAILURE, message);
     }
 
+    public void auditKeyInfo(KeyId keyId, String clientKeyId, String status, String reason) {
+        audit(new SecurityDataInfoEvent(
+                servletRequest.getUserPrincipal().getName(),
+                status,
+                keyId,
+                clientKeyId,
+                (reason != null) ? auditInfo + ";" + reason : auditInfo,
+                null
+        ));
+    }
+
+    public void auditKeyInfoSuccess(KeyId keyid, String clientKeyId) {
+        auditKeyInfo(keyId, clientKeyId, ILogger.SUCCESS, null);
+    }
+
+    public void auditKeyInfoError(KeyId keyId, String clientKeyId, String message) {
+        CMS.debug(message);
+        auditKeyInfo(keyId, clientKeyId, ILogger.FAILURE, message);
+    }
+
     public void auditKeyStatusChange(String status, String keyID, String oldKeyStatus,
             String newKeyStatus, String info) {
         String msg = CMS.getLogMessage(
@@ -634,6 +667,27 @@ public class KeyService extends SubsystemService implements KeyResource {
         auditor.log(msg);
     }
 
+    public void auditRecoveryRequest(String status) {
+        audit(new SecurityDataRecoveryEvent(
+                servletRequest.getUserPrincipal().getName(),
+                status,
+                requestId,
+                keyId,
+                null
+        ));
+    }
+
+    public void auditRecoveryRequestProcessed(String status, String reason) {
+        audit(new SecurityDataRecoveryProcessedEvent(
+                servletRequest.getUserPrincipal().getName(),
+                status,
+                requestId,
+                keyId,
+                (reason != null) ? auditInfo + ";" + reason : auditInfo,
+                approvers
+        ));
+    }
+
     /**
      * Used to retrieve a key
      * @param data
@@ -697,10 +751,10 @@ public class KeyService extends SubsystemService implements KeyResource {
         try {
             return getKeyInfoImpl(keyId);
         } catch (RuntimeException e) {
-            auditError(e.getMessage());
+            auditKeyInfoError(keyId, null, e.getMessage());
             throw e;
         } catch (Exception e) {
-            auditError(e.getMessage());
+            auditKeyInfoError(keyId, null, e.getMessage());
             throw new PKIException(e.getMessage(), e);
         }
     }
@@ -715,7 +769,7 @@ public class KeyService extends SubsystemService implements KeyResource {
             rec = repo.readKeyRecord(keyId.toBigInteger());
             authz.checkRealm(rec.getRealm(), getAuthToken(), rec.getOwnerName(), "certServer.kra.key", "read");
             KeyInfo info = createKeyDataInfo(rec, true);
-            auditRetrieveKey(ILogger.SUCCESS);
+            auditKeyInfoSuccess(keyId, null);
 
             return createOKResponse(info);
         } catch (EAuthzAccessDenied e) {
diff --git a/base/server/cmsbundle/src/LogMessages.properties b/base/server/cmsbundle/src/LogMessages.properties
index 9cdcae687..3b998d99c 100644
--- a/base/server/cmsbundle/src/LogMessages.properties
+++ b/base/server/cmsbundle/src/LogMessages.properties
@@ -2451,7 +2451,7 @@ LOGGING_SIGNED_AUDIT_SECURITY_DATA_RECOVERY_REQUEST=<type=SECURITY_DATA_RECOVERY
 #
 LOGGING_SIGNED_AUDIT_SECURITY_DATA_RECOVERY_REQUEST_STATE_CHANGE_4=<type=SECURITY_DATA_RECOVERY_REQUEST_STATE_CHANGE>:[AuditEvent=SECURITY_DATA_RECOVERY_REQUEST_STATE_CHANGE][SubjectID={0}][Outcome={1}][RecoveryID={2}][Operation={3}] security data recovery request state change
 #
-# LOGGING_SIGNED_AUDIT_SECURITY_DATA_RETRIEVE_KEY
+# LOGGING_SIGNED_AUDIT_SECURITY_DATA_EXPORT_KEY
 # - used when user attempts to retrieve key after the recovery request 
 #   has been approved.
 # 
@@ -2462,6 +2462,16 @@ LOGGING_SIGNED_AUDIT_SECURITY_DATA_RECOVERY_REQUEST_STATE_CHANGE_4=<type=SECURIT
 #
 LOGGING_SIGNED_AUDIT_SECURITY_DATA_EXPORT_KEY=<type=SECURITY_DATA_EXPORT_KEY>:[AuditEvent=SECURITY_DATA_EXPORT_KEY][SubjectID={0}][Outcome={1}][RecoveryID={2}][KeyID={3}][Info={4}][PubKey={5}] security data retrieval request
 #
+# LOGGING_SIGNED_AUDIT_SECURITY_DATA_INFO
+# - used when user attempts to get metadata information about a key 
+# 
+# RecoveryID must be the recovery request ID
+# KeyID is the key being retrieved
+# Info is the failure reason if the export fails.
+# PubKey is the public key for the private key being retrieved
+#
+LOGGING_SIGNED_AUDIT_SECURITY_DATA_INFO=<type=SECURITY_DATA_INFO>:[AuditEvent=SECURITY_DATA_INFO][SubjectID={0}][Outcome={1}][KeyID={2}][ClientKeyId={3}[Info={4}][PubKey={5}] security data info request
+#
 # LOGGING_SIGNED_AUDIT_KEY_STATUS_CHANGE
 # - used when modify key status is executed
 # keyID must be an existing key id in the database