Simplify recovery audit logging

Currently, when we use the retrieveKey() REST interface, there are
two logs generated for the processing of a recovery request.  To
rectify this, logging has been removed from the lower level in the
SecurityDataProcessor and is delegated to the higher level.

This necessitated adding audit logging to the SecurityDataRecoveryService,
which processes recovery events asynchronously.

In addition, the logging in retrieveKey() has been pushed down to
the retrieveKeyImpl, because there is at least one success exit point in
retrieveKeyImpl where a recovery request is created, but no key is exported.
Hence in this case, a KeyRetrieve success event is not warranted.

Change-Id: I0725e6fe82046ae666bf6c81d6a6ba58261dfc87

3 files changed, 72 insertions, 38 deletions

diff --git a/base/kra/src/com/netscape/kra/SecurityDataProcessor.java b/base/kra/src/com/netscape/kra/SecurityDataProcessor.java
index 326630c69..2899f3254 100644
--- a/base/kra/src/com/netscape/kra/SecurityDataProcessor.java
+++ b/base/kra/src/com/netscape/kra/SecurityDataProcessor.java
@@ -42,7 +42,6 @@ import com.netscape.certsrv.kra.IKeyRecoveryAuthority;
 import com.netscape.certsrv.logging.AuditEvent;
 import com.netscape.certsrv.logging.ILogger;
 import com.netscape.certsrv.logging.event.SecurityDataArchivalProcessedEvent;
-import com.netscape.certsrv.logging.event.SecurityDataRecoveryProcessedEvent;
 import com.netscape.certsrv.profile.IEnrollProfile;
 import com.netscape.certsrv.request.IRequest;
 import com.netscape.certsrv.request.RequestId;
@@ -322,20 +321,13 @@ public class SecurityDataProcessor {
             throw new EBaseException(CMS.getUserMessage("CMS_BASE_CERT_ERROR", e.toString()));
         }
 
-        String requestor = request.getExtDataInString(IRequest.ATTR_REQUEST_OWNER);
-        String auditSubjectID = requestor;
-
         Hashtable<String, Object> params = kra.getVolatileRequest(
                 request.getRequestId());
         KeyId keyId = new KeyId(request.getExtDataInBigInteger(ATTR_SERIALNO));
         request.setExtData(ATTR_KEY_RECORD, keyId.toBigInteger());
-        RequestId requestID = request.getRequestId();
-        String approvers = request.getExtDataInString(IRequest.ATTR_APPROVE_AGENTS);
 
         if (params == null) {
             CMS.debug("SecurityDataProcessor.recover(): Can't get volatile params.");
-            auditRecoveryRequestProcessed(auditSubjectID, ILogger.FAILURE, requestID, keyId,
-                    "cannot get volatile params", approvers);
             throw new EBaseException("Can't obtain volatile params!");
         }
 
@@ -457,8 +449,6 @@ public class SecurityDataProcessor {
                     iv != null? new IVParameterSpec(iv): null,
                     iv_wrap != null? new IVParameterSpec(iv_wrap): null);
             } catch (Exception e) {
-                auditRecoveryRequestProcessed(auditSubjectID, ILogger.FAILURE, requestID, keyId,
-                        "Cannot generate wrapping params", approvers);
                 throw new EBaseException("Cannot generate wrapping params: " + e, e);
             }
         }
@@ -514,8 +504,6 @@ public class SecurityDataProcessor {
                 params.put(IRequest.SECURITY_DATA_PASS_WRAPPED_DATA, pbeWrappedData);
 
             } catch (Exception e) {
-                auditRecoveryRequestProcessed(auditSubjectID, ILogger.FAILURE, requestID, keyId,
-                        "Cannot unwrap passphrase", approvers);
                 throw new EBaseException("Cannot unwrap passphrase: " + e, e);
 
             } finally {
@@ -556,8 +544,6 @@ public class SecurityDataProcessor {
                     }
 
                 } catch (Exception e) {
-                    auditRecoveryRequestProcessed(auditSubjectID, ILogger.FAILURE, requestID, keyId,
-                            "Cannot wrap symmetric key", approvers);
                     throw new EBaseException("Cannot wrap symmetric key: " + e, e);
                 }
 
@@ -574,8 +560,6 @@ public class SecurityDataProcessor {
                             wrapParams.getPayloadEncryptionAlgorithm(),
                             wrapParams.getPayloadEncryptionIV());
                 } catch (Exception e) {
-                    auditRecoveryRequestProcessed(auditSubjectID, ILogger.FAILURE, requestID,
-                            keyId, "Cannot encrypt passphrase", approvers);
                     throw new EBaseException("Cannot encrypt passphrase: " + e, e);
                 }
 
@@ -606,8 +590,6 @@ public class SecurityDataProcessor {
                     }
 
                 } catch (Exception e) {
-                    auditRecoveryRequestProcessed(auditSubjectID, ILogger.FAILURE, requestID, keyId,
-                            "Cannot wrap private key", approvers);
                     throw new EBaseException("Cannot wrap private key: " + e, e);
                 }
             }
@@ -640,9 +622,6 @@ public class SecurityDataProcessor {
         }
 
         params.put(IRequest.SECURITY_DATA_TYPE, dataType);
-
-        auditRecoveryRequestProcessed(auditSubjectID, ILogger.SUCCESS, requestID, keyId,
-                null, approvers);
         request.setExtData(IRequest.RESULT, IRequest.RES_SUCCESS);
 
         return false; //return true ? TODO
@@ -857,17 +836,6 @@ public class SecurityDataProcessor {
         audit(message);
     }
 
-    private void auditRecoveryRequestProcessed(String subjectID, String status, RequestId requestID,
-            KeyId keyID, String reason, String recoveryAgents) {
-        audit(new SecurityDataRecoveryProcessedEvent(
-                subjectID,
-                status,
-                requestID,
-                keyID,
-                reason,
-                recoveryAgents));
-    }
-
     private void auditArchivalRequestProcessed(String subjectID, String status, RequestId requestID, String clientKeyID,
             KeyId keyID, String reason) {
         audit(new SecurityDataArchivalProcessedEvent(
diff --git a/base/kra/src/com/netscape/kra/SecurityDataRecoveryService.java b/base/kra/src/com/netscape/kra/SecurityDataRecoveryService.java
index 0c7b4b70e..da82e97a2 100644
--- a/base/kra/src/com/netscape/kra/SecurityDataRecoveryService.java
+++ b/base/kra/src/com/netscape/kra/SecurityDataRecoveryService.java
@@ -19,9 +19,14 @@ package com.netscape.kra;
 
 import com.netscape.certsrv.apps.CMS;
 import com.netscape.certsrv.base.EBaseException;
+import com.netscape.certsrv.dbs.keydb.KeyId;
 import com.netscape.certsrv.kra.IKeyRecoveryAuthority;
+import com.netscape.certsrv.logging.AuditEvent;
+import com.netscape.certsrv.logging.ILogger;
+import com.netscape.certsrv.logging.event.SecurityDataRecoveryProcessedEvent;
 import com.netscape.certsrv.request.IRequest;
 import com.netscape.certsrv.request.IService;
+import com.netscape.certsrv.request.RequestId;
 
 /**
  * This implementation services SecurityData Recovery requests.
@@ -33,6 +38,7 @@ public class SecurityDataRecoveryService implements IService {
 
     private IKeyRecoveryAuthority kra = null;
     private SecurityDataProcessor processor = null;
+    private ILogger signedAuditLogger = CMS.getSignedAuditLogger();
 
     public SecurityDataRecoveryService(IKeyRecoveryAuthority kra) {
         this.kra = kra;
@@ -57,8 +63,65 @@ public class SecurityDataRecoveryService implements IService {
             throws EBaseException {
 
         CMS.debug("SecurityDataRecoveryService.serviceRequest()");
-        processor.recover(request);
-        kra.getRequestQueue().updateRequest(request);
+
+        // parameters for auditing
+        String auditSubjectID = request.getExtDataInString(IRequest.ATTR_REQUEST_OWNER);
+        KeyId keyId = new KeyId(request.getExtDataInBigInteger("serialNumber"));
+        RequestId requestID = request.getRequestId();
+        String approvers = request.getExtDataInString(IRequest.ATTR_APPROVE_AGENTS);
+
+        try {
+            processor.recover(request);
+            kra.getRequestQueue().updateRequest(request);
+            auditRecoveryRequestProcessed(
+                    auditSubjectID,
+                    ILogger.SUCCESS,
+                    requestID,
+                    keyId,
+                    null,
+                    approvers);
+        } catch (EBaseException e) {
+            auditRecoveryRequestProcessed(
+                    auditSubjectID,
+                    ILogger.FAILURE,
+                    requestID,
+                    keyId,
+                    e.getMessage(),
+                    approvers);
+            throw e;
+        }
         return false;  //TODO: return true?
     }
+
+    private void audit(AuditEvent event) {
+
+        String template = event.getMessage();
+        Object[] params = event.getParameters();
+
+        String message = CMS.getLogMessage(template, params);
+
+        audit(message);
+    }
+
+    private void audit(String msg) {
+        if (signedAuditLogger == null)
+            return;
+
+        signedAuditLogger.log(ILogger.EV_SIGNED_AUDIT,
+                null,
+                ILogger.S_SIGNED_AUDIT,
+                ILogger.LL_SECURITY,
+                msg);
+    }
+
+    private void auditRecoveryRequestProcessed(String subjectID, String status, RequestId requestID,
+            KeyId keyID, String reason, String recoveryAgents) {
+        audit(new SecurityDataRecoveryProcessedEvent(
+                subjectID,
+                status,
+                requestID,
+                keyID,
+                reason,
+                recoveryAgents));
+    }
 }
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 52799e67f..8edb92892 100644
--- a/base/kra/src/org/dogtagpki/server/kra/rest/KeyService.java
+++ b/base/kra/src/org/dogtagpki/server/kra/rest/KeyService.java
@@ -117,13 +117,10 @@ public class KeyService extends SubsystemService implements KeyResource {
     public Response retrieveKey(KeyRecoveryRequest data) {
         try {
             Response response = retrieveKeyImpl(data);
-            auditRetrieveKey(ILogger.SUCCESS);
             return response;
         } catch(RuntimeException e) {
-            auditRetrieveKeyError(e.getMessage());
             throw e;
         } catch (Exception e) {
-            auditRetrieveKeyError(e.getMessage());
             throw new PKIException(e.getMessage(), e);
         }
     }
@@ -137,6 +134,7 @@ public class KeyService extends SubsystemService implements KeyResource {
         CMS.debug(auditInfo);
 
         if (data == null) {
+            auditRetrieveKeyError("Bad Request: Missing key Recovery Request");
             throw new BadRequestException("Missing key Recovery Request");
         }
 
@@ -152,10 +150,12 @@ public class KeyService extends SubsystemService implements KeyResource {
             try {
                 request = queue.findRequest(requestId);
             } catch (EBaseException e) {
+                auditRetrieveKeyError(e.getMessage());
                 throw new PKIException(e.getMessage(), e);
             }
 
             if (request == null) {
+                auditRetrieveKeyError("Bad Request: No request found");
                 throw new BadRequestException("No request found");
             }
 
@@ -166,7 +166,8 @@ public class KeyService extends SubsystemService implements KeyResource {
         } else {
             keyId = data.getKeyId();
             if (keyId == null) {
-                throw new BadRequestException("Missing key Recovery Request");
+                auditRetrieveKeyError("Bad Request: Missing key recovery request and key_id");
+                throw new BadRequestException("Missing recovery request and key id");
             }
 
             auditInfo += ";keyID=" + keyId.toString();
@@ -186,6 +187,7 @@ public class KeyService extends SubsystemService implements KeyResource {
                 request = reqDAO.createRecoveryRequest(data, uriInfo, getRequestor(),
                         getAuthToken(), ephemeral);
             } catch (EBaseException e) {
+                auditRetrieveKeyError("Unable to create recovery request: " + e.getMessage());
                 throw new PKIException(e.getMessage(), e);
             }
 
@@ -248,6 +250,7 @@ public class KeyService extends SubsystemService implements KeyResource {
         auditRecoveryRequestProcessed(ILogger.SUCCESS, null);
 
         CMS.debug("KeyService: key retrieved");
+        auditRetrieveKey(ILogger.SUCCESS);
         return createOKResponse(keyData);
     }