Ticket #2335 Missing activity logs when formatting/enrolling unknown token

This patch adds activity logs for adding unknown token during format or enrollment or pin reset.

4 files changed, 48 insertions, 56 deletions

diff --git a/base/tps/src/org/dogtagpki/server/tps/TPSTokendb.java b/base/tps/src/org/dogtagpki/server/tps/TPSTokendb.java
index ed7e022fa..e9190d09a 100644
--- a/base/tps/src/org/dogtagpki/server/tps/TPSTokendb.java
+++ b/base/tps/src/org/dogtagpki/server/tps/TPSTokendb.java
@@ -180,19 +180,18 @@ public class TPSTokendb {
 
     public void tdbUpdateTokenEntry(TokenRecord tokenRecord)
             throws Exception {
+        String method = "TPSTokendb.tdbUpdateTokenEntry:";
         String id = tokenRecord.getId();
         TokenRecord existingTokenRecord;
         try {
             existingTokenRecord = tps.tokenDatabase.getRecord(id);
         } catch (EDBRecordNotFoundException e) {
-            CMS.debug("TPSTokendb.tdbUpdateTokenEntry: " + e);
-            CMS.debug("TPSTokendb.tdbUpdateTokenEntry: Adding token " + id);
-            // add and exit
-            tdbAddTokenEntry(tokenRecord, TokenStatus.FORMATTED);
-            return;
+            String logMsg = method + e;
+            CMS.debug(logMsg);
+            throw new TPSException(logMsg, TPSStatus.STATUS_ERROR_CONTACT_ADMIN);
         }
         // token found; modify
-        CMS.debug("TPSTokendb.tdbUpdateTokenEntry: token entry found; Modifying with status: " + tokenRecord.getTokenStatus());
+        CMS.debug(method + " token entry found; Modifying with status: " + tokenRecord.getTokenStatus());
         // don't change the create time of an existing token record; put it back
         tokenRecord.setCreateTimestamp(existingTokenRecord.getCreateTimestamp());
         tps.tokenDatabase.updateRecord(id, tokenRecord);
diff --git a/base/tps/src/org/dogtagpki/server/tps/processor/TPSEnrollProcessor.java b/base/tps/src/org/dogtagpki/server/tps/processor/TPSEnrollProcessor.java
index 24b2dbf82..6240ea69c 100644
--- a/base/tps/src/org/dogtagpki/server/tps/processor/TPSEnrollProcessor.java
+++ b/base/tps/src/org/dogtagpki/server/tps/processor/TPSEnrollProcessor.java
@@ -266,7 +266,7 @@ public class TPSEnrollProcessor extends TPSProcessor {
                 }
             } catch (TPSException e) {
                 logMsg = e.toString();
-                tps.tdb.tdbActivity(ActivityDatabase.OP_FORMAT, tokenRecord, session.getIpAddress(), logMsg,
+                tps.tdb.tdbActivity(ActivityDatabase.OP_ENROLLMENT, tokenRecord, session.getIpAddress(), logMsg,
                         "failure");
 
                 throw new TPSException(logMsg, TPSStatus.STATUS_ERROR_MISCONFIGURATION);
@@ -301,6 +301,7 @@ public class TPSEnrollProcessor extends TPSProcessor {
             }
 
             do_force_format = tokenPolicy.isForceTokenFormat(cuid);
+            CMS.debug(method + " Will force format first due to policy.");
 
             if (!isExternalReg &&
                     !tokenPolicy.isAllowdTokenReenroll(cuid) &&
@@ -319,9 +320,9 @@ public class TPSEnrollProcessor extends TPSProcessor {
             }
         } else {
             CMS.debug(method + " token does not exist");
-            tokenRecord.setTokenStatus(TokenStatus.FORMATTED);
-
             checkAllowUnknownToken(TPSEngine.OP_FORMAT_PREFIX);
+            CMS.debug(method + "force a format");
+            do_force_format = true;
         }
 
         // isExternalReg : user already authenticated earlier
@@ -329,7 +330,6 @@ public class TPSEnrollProcessor extends TPSProcessor {
             checkAndAuthenticateUser(appletInfo, getSelectedTokenType());
 
         if (do_force_format) {
-            CMS.debug(method + " About to force format first due to policy.");
             //We will skip the auth step inside of format
             format(true);
         } else {
@@ -366,18 +366,6 @@ public class TPSEnrollProcessor extends TPSProcessor {
 
         pkcs11objx.setCUID(appletInfo.getCUID());
 
-        if (!isTokenPresent) {
-            try {
-                tps.tdb.tdbAddTokenEntry(tokenRecord, TokenStatus.FORMATTED);
-            } catch (Exception e) {
-                String failMsg = "add token failure";
-                logMsg = failMsg + ":" + e.toString();
-                tps.tdb.tdbActivity(ActivityDatabase.OP_ENROLLMENT, tokenRecord, session.getIpAddress(), logMsg,
-                        "failure");
-                throw new TPSException(logMsg);
-            }
-        }
-
         statusUpdate(10, "PROGRESS_PROCESS_PROFILE");
 
         EnrolledCertsInfo certsInfo = new EnrolledCertsInfo();
@@ -397,6 +385,7 @@ public class TPSEnrollProcessor extends TPSProcessor {
         }
 
         //most failed would have thrown an exception
+        logMsg = " generateCertsAfterRenewalRecoveryPolicy returned status=" + status;
         String statusString = "Unknown"; // gives some meaningful debug message
         if (status == TPSStatus.STATUS_NO_ERROR)
             statusString = "Enrollment to follow";
@@ -409,7 +398,6 @@ public class TPSEnrollProcessor extends TPSProcessor {
             renewed = true;
             tps.tdb.tdbActivity(ActivityDatabase.OP_RENEWAL, tokenRecord, session.getIpAddress(), logMsg, "success");
         } else {
-            logMsg = " generateCertsAfterRenewalRecoveryPolicy returned status=" + status;
             CMS.debug(method + logMsg);
             tps.tdb.tdbActivity(ActivityDatabase.OP_ENROLLMENT, tokenRecord, session.getIpAddress(), logMsg,
                     "failure");
@@ -535,17 +523,6 @@ public class TPSEnrollProcessor extends TPSProcessor {
 
         statusUpdate(99, "PROGRESS_SET_LIFECYCLE");
         channel.setLifeycleState((byte) 0x0f);
-
-        try {
-            tokenRecord.setTokenStatus(TokenStatus.ACTIVE);
-            tps.tdb.tdbUpdateTokenEntry(tokenRecord);
-        } catch (Exception e) {
-            String failMsg = "update token failure";
-            logMsg = failMsg + ":" + e.toString();
-            tps.tdb.tdbActivity(ActivityDatabase.OP_ENROLLMENT, tokenRecord, session.getIpAddress(), logMsg,
-                    "failure");
-            throw new TPSException(logMsg);
-        }
         //update the tokendb with new certs
         CMS.debug(method + " updating tokendb with certs.");
         try {
@@ -566,8 +543,16 @@ public class TPSEnrollProcessor extends TPSProcessor {
 
         logMsg = "appletVersion=" + lastObjVer + "; tokenType =" + selectedTokenType + "; userid =" + userid;
         CMS.debug(method + logMsg);
-        tps.tdb.tdbActivity(ActivityDatabase.OP_ENROLLMENT, tokenRecord, session.getIpAddress(), logMsg,
-                "success");
+        try {
+            tokenRecord.setTokenStatus(TokenStatus.ACTIVE);
+            tps.tdb.tdbUpdateTokenEntry(tokenRecord);
+            tps.tdb.tdbActivity(ActivityDatabase.OP_ENROLLMENT, tokenRecord, session.getIpAddress(), logMsg, "success");
+        } catch (Exception e) {
+            logMsg = logMsg + ":" + e.toString();
+            tps.tdb.tdbActivity(ActivityDatabase.OP_ENROLLMENT, tokenRecord, session.getIpAddress(), logMsg,
+                    "failure");
+            throw new TPSException(logMsg);
+        }
 
         CMS.debug(method + " leaving ...");
 
diff --git a/base/tps/src/org/dogtagpki/server/tps/processor/TPSPinResetProcessor.java b/base/tps/src/org/dogtagpki/server/tps/processor/TPSPinResetProcessor.java
index d9a79f4f0..9d0625a31 100644
--- a/base/tps/src/org/dogtagpki/server/tps/processor/TPSPinResetProcessor.java
+++ b/base/tps/src/org/dogtagpki/server/tps/processor/TPSPinResetProcessor.java
@@ -78,7 +78,7 @@ public class TPSPinResetProcessor extends TPSProcessor {
             // appletInfo is null as expected at this point
             // but audit for the record anyway
             auditOpRequest("pinReset", appletInfo, "failure", logMsg);
-            tps.tdb.tdbActivity(ActivityDatabase.OP_ENROLLMENT, tokenRecord, session.getIpAddress(), logMsg,
+            tps.tdb.tdbActivity(ActivityDatabase.OP_PIN_RESET, tokenRecord, session.getIpAddress(), logMsg,
                     "failure");
 
             throw e;
@@ -89,10 +89,12 @@ public class TPSPinResetProcessor extends TPSProcessor {
 
         if (tokenRecord == null) {
             //We can't reset the pin of a token that does not exist.
-            logMsg = "Token does not exist!";
+            logMsg = method + "Token does not exist!";
             auditPinReset(session.getIpAddress(), userid, appletInfo, "failure", null, logMsg);
-            CMS.debug(method + ": " + logMsg);
-            throw new TPSException(method + logMsg +
+            tps.tdb.tdbActivity(ActivityDatabase.OP_PIN_RESET, tokenRecord, session.getIpAddress(), logMsg,
+                    "failure");
+            CMS.debug(logMsg);
+            throw new TPSException(logMsg +
                     TPSStatus.STATUS_ERROR_MAC_RESET_PIN_PDU);
         }
 
@@ -153,23 +155,19 @@ public class TPSPinResetProcessor extends TPSProcessor {
         auditPinReset(session.getIpAddress(), userid, appletInfo, "success",
                 channel.getKeyInfoData().toHexStringPlain(), null);
 
+        statusUpdate(100, "PROGRESS_PIN_RESET_COMPLETE");
+        logMsg = "update token during pin reset";
         try {
             tps.tdb.tdbUpdateTokenEntry(tokenRecord);
+            tps.tdb.tdbActivity(ActivityDatabase.OP_PIN_RESET, tokenRecord, session.getIpAddress(), logMsg, "success");
             CMS.debug(method + ": token record updated!");
         } catch (Exception e) {
-            String failMsg = "update token failure";
-            logMsg = failMsg + ":" + e.toString();
+            logMsg = logMsg + ":" + e.toString();
             tps.tdb.tdbActivity(ActivityDatabase.OP_PIN_RESET, tokenRecord, session.getIpAddress(), logMsg,
                     "failure");
             throw new TPSException(logMsg);
         }
 
-        statusUpdate(100, "PROGRESS_PIN_RESET_COMPLETE");
-
-        logMsg = "pin reset operation completed successfully";
-        tps.tdb.tdbActivity(ActivityDatabase.OP_PIN_RESET, tokenRecord, session.getIpAddress(), logMsg,
-                "success");
-
         CMS.debug(method + ": Token Pin successfully reset!");
 
     }
diff --git a/base/tps/src/org/dogtagpki/server/tps/processor/TPSProcessor.java b/base/tps/src/org/dogtagpki/server/tps/processor/TPSProcessor.java
index 26c438b3a..ff6420879 100644
--- a/base/tps/src/org/dogtagpki/server/tps/processor/TPSProcessor.java
+++ b/base/tps/src/org/dogtagpki/server/tps/processor/TPSProcessor.java
@@ -2119,9 +2119,22 @@ public class TPSProcessor {
                         " to " + newState);
             }
         } else {
+            checkAllowUnknownToken(TPSEngine.OP_FORMAT_PREFIX);
+
+            tokenRecord.setTokenStatus(TokenStatus.UNFORMATTED);
             CMS.debug("TPSProcessor.format: token does not exist");
+            logMsg = "add token during format";
+            try {
+                tps.tdb.tdbAddTokenEntry(tokenRecord, TokenStatus.UNFORMATTED);
+                tps.tdb.tdbActivity(ActivityDatabase.OP_ADD, tokenRecord, session.getIpAddress(), logMsg, "success");
+                CMS.debug("TPSProcessor.format: token added");
+            } catch (Exception e) {
+                logMsg = logMsg + ":" + e.toString();
+                tps.tdb.tdbActivity(ActivityDatabase.OP_ADD, tokenRecord, session.getIpAddress(), logMsg,
+                        "failure");
+                throw new TPSException(logMsg);
+            }
 
-            checkAllowUnknownToken(TPSEngine.OP_FORMAT_PREFIX);
         }
 
         // TODO: the following lines of code could be replaced with call to
@@ -2205,21 +2218,18 @@ public class TPSProcessor {
 
         // Update Token DB
         tokenRecord.setTokenStatus(TokenStatus.FORMATTED);
+        logMsg = "token format operation";
         try {
             tps.tdb.tdbUpdateTokenEntry(tokenRecord);
+            tps.tdb.tdbActivity(ActivityDatabase.OP_FORMAT, tokenRecord, session.getIpAddress(), logMsg, "success");
         } catch (Exception e) {
-            String failMsg = "update token failure";
-            logMsg = failMsg + ":" + e.toString();
-            tps.tdb.tdbActivity(ActivityDatabase.OP_FORMAT, tokenRecord, session.getIpAddress(), failMsg,
+            logMsg = logMsg + ":" + e.toString();
+            tps.tdb.tdbActivity(ActivityDatabase.OP_FORMAT, tokenRecord, session.getIpAddress(), logMsg,
                     "failure");
 
             throw new TPSException(logMsg, TPSStatus.STATUS_ERROR_CONTACT_ADMIN);
         }
 
-        logMsg = "format operation succeeded";
-
-        tps.tdb.tdbActivity(ActivityDatabase.OP_FORMAT, tokenRecord, session.getIpAddress(), logMsg, "success");
-
         CMS.debug("TPSProcessor.format:: ends");
 
     }