Have the action service record when actions run, and if they worked

Handles persisting this action data for sucessful actions
(Failure information persistance still to follow)
Includes lots of unit tests for working and failing sync and async actions


git-svn-id: https://svn.alfresco.com/repos/alfresco-enterprise/alfresco/HEAD/root@21175 c4b6b30b-aa2e-2d43-bbcb-ca4b014f7261

source/java/org/alfresco/repo/action/ActionServiceImpl.java

@@ -618,7 +618,7 @@ public class ActionServiceImpl implements ActionService, RuntimeActionService, A
             logger.debug(builder.toString());
             logger.debug("Current action = " + action.getId());
         }
-
+        
         // get the current user early in case the process fails and we are
         // unable to do it later
         String currentUserName = this.authenticationContext.getCurrentUserName();
@@ -655,8 +655,21 @@ public class ActionServiceImpl implements ActionService, RuntimeActionService, A
                     // Check and execute now
                     if (checkConditions == false || evaluateAction(action, actionedUponNodeRef) == true)
                     {
+                        // Mark the action as starting
+                        ((ActionImpl)action).setExecutionStartDate(new Date());
+                        ((ActionImpl)action).setExecutionStatus(ActionStatus.Running);
+
                         // Execute the action
                         directActionExecution(action, actionedUponNodeRef);
+                        
+                        // Mark it as having worked
+                        ((ActionImpl)action).setExecutionEndDate(new Date());
+                        ((ActionImpl)action).setExecutionStatus(ActionStatus.Completed);
+                        ((ActionImpl)action).setExecutionFailureMessage(null);
+                        if(action.getNodeRef() != null)
+                        {
+                           saveActionImpl(action.getNodeRef(), action);
+                        }
                     }
                 }
                 finally
@@ -693,6 +706,9 @@ public class ActionServiceImpl implements ActionService, RuntimeActionService, A
                         queueAction(compensatingAction, actionedUponNodeRef);
                     }
                 }
+                
+                // Have the failure logged on the action
+                recordActionFailure(action, exception);
 
                 // Rethrow the exception
                 if (exception instanceof RuntimeException)
@@ -707,6 +723,27 @@ public class ActionServiceImpl implements ActionService, RuntimeActionService, A
             }
         }
     }
+    
+    /**
+     * Schedule the recording of the action failure to occur
+     *  in another transaction
+     */
+    protected void recordActionFailure(Action action, Throwable exception)
+    {
+       if (logger.isDebugEnabled() == true)
+       {
+          logger.debug("Recording failure of action " + action + " due to " + exception.getMessage());
+       }
+       
+       ((ActionImpl)action).setExecutionEndDate(new Date());
+       ((ActionImpl)action).setExecutionStatus(ActionStatus.Failed);
+       ((ActionImpl)action).setExecutionFailureMessage(exception.getMessage());
+       
+       if(action.getNodeRef() != null)
+       {
+          // TODO
+       }
+    }
 
     /**
      * @see org.alfresco.repo.action.RuntimeActionService#directActionExecution(org.alfresco.service.cmr.action.Action,
@@ -1531,6 +1568,7 @@ public class ActionServiceImpl implements ActionService, RuntimeActionService, A
             if (pendingActions.contains(pendingAction) == false)
             {
                 pendingActions.add(pendingAction);
+                ((ActionImpl)action).setExecutionStatus(ActionStatus.Pending);
             }
         }
     }

source/java/org/alfresco/repo/action/ActionServiceImplTest.java

@@ -68,6 +68,7 @@ public class ActionServiceImplTest extends BaseAlfrescoSpringTest
     
     private NodeRef nodeRef;
     private NodeRef folder;
+    private RuntimeActionService runtimeActionService;
     private RetryingTransactionHelper transactionHelper;
     
 //    @Override
@@ -89,6 +90,7 @@ public class ActionServiceImplTest extends BaseAlfrescoSpringTest
         super.onSetUpInTransaction();
 
         this.transactionHelper = (RetryingTransactionHelper)this.applicationContext.getBean("retryingTransactionHelper");
+        this.runtimeActionService = (RuntimeActionService)this.applicationContext.getBean("actionService");
 
         // Create the node used for tests
         this.nodeRef = this.nodeService.createNode(
@@ -106,6 +108,14 @@ public class ActionServiceImplTest extends BaseAlfrescoSpringTest
                 QName.createQName("{test}testFolder"),
                 ContentModel.TYPE_FOLDER).getChildRef();
         
+        // Register the test executor, if needed
+        if(!applicationContext.containsBean(SleepActionExecuter.NAME))
+        {
+           applicationContext.getBeanFactory().registerSingleton(
+                 SleepActionExecuter.NAME,
+                 new SleepActionExecuter()
+           );
+        }
     }
     
     /**
@@ -1029,12 +1039,7 @@ public class ActionServiceImplTest extends BaseAlfrescoSpringTest
     public void testSyncFailureBehaviour()
     {
         // Create an action that is going to fail
-        Action action = this.actionService.createAction(MoveActionExecuter.NAME);
-        action.setParameterValue(MoveActionExecuter.PARAM_ASSOC_TYPE_QNAME, ContentModel.ASSOC_CHILDREN);
-        action.setParameterValue(MoveActionExecuter.PARAM_ASSOC_QNAME, ContentModel.ASSOC_CHILDREN);
-        // Create a bad node ref
-        NodeRef badNodeRef = new NodeRef(this.storeRef, "123123");
-        action.setParameterValue(MoveActionExecuter.PARAM_DESTINATION_FOLDER, badNodeRef);
+        Action action = createFailingMoveAction();
         
         try
         {
@@ -1079,12 +1084,7 @@ public class ActionServiceImplTest extends BaseAlfrescoSpringTest
     public void testCompensatingAction()
     {
         // Create an action that is going to fail
-        final Action action = this.actionService.createAction(MoveActionExecuter.NAME);
-        action.setParameterValue(MoveActionExecuter.PARAM_ASSOC_TYPE_QNAME, ContentModel.ASSOC_CHILDREN);
-        action.setParameterValue(MoveActionExecuter.PARAM_ASSOC_QNAME, ContentModel.ASSOC_CHILDREN);
-        // Create a bad node ref
-        NodeRef badNodeRef = new NodeRef(this.storeRef, "123123");
-        action.setParameterValue(MoveActionExecuter.PARAM_DESTINATION_FOLDER, badNodeRef);
+        final Action action = createFailingMoveAction();
         action.setTitle("title");
         
         // Create the compensating action
@@ -1212,8 +1212,300 @@ public class ActionServiceImplTest extends BaseAlfrescoSpringTest
      *  working or failing, that the action execution
      *  service correctly sets the flags
      */
-    public void testExecutionTrackingOnExecution() {
-       // TODO
+    public void testExecutionTrackingOnExecution() throws Exception {
+       final SleepActionExecuter sleepActionExec = new SleepActionExecuter();
+       sleepActionExec.setSleepMs(10);
+       Action action;
+       NodeRef actionNode;
+
+       
+       // ===========================================================
+       //    Execute a transient Action that works, synchronously
+       // ===========================================================
+       action = createWorkingSleepAction();
+       assertNull(action.getExecutionStartDate());
+       assertNull(action.getExecutionEndDate());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.New, action.getExecutionStatus());
+       
+       this.actionService.executeAction(action, this.nodeRef);
+       
+       assertNotNull(action.getExecutionStartDate());
+       assertNotNull(action.getExecutionEndDate());
+       assertBefore(action.getExecutionStartDate(), action.getExecutionEndDate());
+       assertBefore(action.getExecutionEndDate(), new Date());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Completed, action.getExecutionStatus());
+       
+       
+       // ===========================================================
+       //    Execute a transient Action that fails, synchronously
+       // ===========================================================
+       action = createFailingMoveAction();
+       assertNull(action.getExecutionStartDate());
+       assertNull(action.getExecutionEndDate());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.New, action.getExecutionStatus());
+       
+       try {
+          this.actionService.executeAction(action, this.nodeRef);
+          fail("Action should have failed, and the error been thrown");
+       } catch(Exception e) {}
+       
+       assertNotNull(action.getExecutionStartDate());
+       assertNotNull(action.getExecutionEndDate());
+       assertBefore(action.getExecutionStartDate(), action.getExecutionEndDate());
+       assertBefore(action.getExecutionEndDate(), new Date());
+       assertNotNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Failed, action.getExecutionStatus());
+       
+       // Tidy up from the action failure
+       endTransaction();
+       startNewTransaction();
+       onSetUpInTransaction();
+       
+       
+       // ===========================================================
+       //    Execute a stored Action that works, synchronously
+       // ===========================================================
+       action = createWorkingSleepAction();
+       this.actionService.saveAction(this.nodeRef, action);
+       actionNode = action.getNodeRef();
+       assertNotNull(actionNode);
+       
+       assertNull(action.getExecutionStartDate());
+       assertNull(action.getExecutionEndDate());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.New, action.getExecutionStatus());
+       
+       this.actionService.executeAction(action, this.nodeRef);
+       
+       // Check our copy
+       assertNotNull(action.getExecutionStartDate());
+       assertNotNull(action.getExecutionEndDate());
+       assertBefore(action.getExecutionStartDate(), action.getExecutionEndDate());
+       assertBefore(action.getExecutionEndDate(), new Date());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Completed, action.getExecutionStatus());
+       
+       // Now re-load and check the stored one
+       action = runtimeActionService.createAction(actionNode);
+       assertNotNull(action.getExecutionStartDate());
+       assertNotNull(action.getExecutionEndDate());
+       assertBefore(action.getExecutionStartDate(), action.getExecutionEndDate());
+       assertBefore(action.getExecutionEndDate(), new Date());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Completed, action.getExecutionStatus());
+
+       
+       // ===========================================================
+       //    Execute a stored Action that fails, synchronously
+       // ===========================================================
+       action = createFailingMoveAction();
+       this.actionService.saveAction(this.nodeRef, action);
+       actionNode = action.getNodeRef();
+       assertNotNull(actionNode);
+       
+       assertNull(action.getExecutionStartDate());
+       assertNull(action.getExecutionEndDate());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.New, action.getExecutionStatus());
+       
+       try {
+          this.actionService.executeAction(action, this.nodeRef);
+          fail("Action should have failed, and the error been thrown");
+       } catch(Exception e) {}
+
+       // Check our copy
+       assertNotNull(action.getExecutionStartDate());
+       assertNotNull(action.getExecutionEndDate());
+       assertBefore(action.getExecutionStartDate(), action.getExecutionEndDate());
+       assertBefore(action.getExecutionEndDate(), new Date());
+       assertNotNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Failed, action.getExecutionStatus());
+       
+       // Now re-load and check the stored one
+       action = runtimeActionService.createAction(actionNode);
+       // TODO - Fix these
+//       assertNotNull(action.getExecutionStartDate());
+//       assertNotNull(action.getExecutionEndDate());
+//       assertBefore(action.getExecutionStartDate(), action.getExecutionEndDate());
+//       assertBefore(action.getExecutionEndDate(), new Date());
+//       assertNotNull(action.getExecutionFailureMessage());
+//       assertEquals(ActionStatus.Failed, action.getExecutionStatus());
+
+       // Tidy up from the action failure
+       endTransaction();
+       startNewTransaction();
+       onSetUpInTransaction();
+       
+       
+       // ===========================================================
+       //    Execute a transient Action that works, asynchronously
+       // ===========================================================
+       action = createWorkingSleepAction();
+       assertNull(action.getExecutionStartDate());
+       assertNull(action.getExecutionEndDate());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.New, action.getExecutionStatus());
+       
+       this.actionService.executeAction(action, this.nodeRef, false, true);
+       assertNull(action.getExecutionStartDate());
+       assertNull(action.getExecutionEndDate());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Pending, action.getExecutionStatus());
+       setComplete();
+       // End the transaction. When run from a test, this call will
+       //  block until the "async" action has finished running
+       endTransaction();
+       Thread.sleep(100);
+       
+       assertNotNull(action.getExecutionStartDate());
+       assertNotNull(action.getExecutionEndDate());
+       assertBefore(action.getExecutionStartDate(), action.getExecutionEndDate());
+       assertBefore(action.getExecutionEndDate(), new Date());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Completed, action.getExecutionStatus());
+       
+       // Put things back ready for the next check
+       startNewTransaction();
+       onSetUpInTransaction();
+       
+       
+       // ===========================================================
+       //    Execute a transient Action that fails, asynchronously
+       // ===========================================================
+       action = createFailingMoveAction();
+       assertNull(action.getExecutionStartDate());
+       assertNull(action.getExecutionEndDate());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.New, action.getExecutionStatus());
+       
+       this.actionService.executeAction(action, this.nodeRef, false, true);
+       assertNull(action.getExecutionStartDate());
+       assertNull(action.getExecutionEndDate());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Pending, action.getExecutionStatus());
+       setComplete();
+       // End the transaction. When run from a test, this call will
+       //  block until the "async" action has finished running
+       endTransaction();
+       Thread.sleep(100);
+       
+       assertNotNull(action.getExecutionStartDate());
+       assertNotNull(action.getExecutionEndDate());
+       assertBefore(action.getExecutionStartDate(), action.getExecutionEndDate());
+       assertBefore(action.getExecutionEndDate(), new Date());
+       assertNotNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Failed, action.getExecutionStatus());
+       
+       // Put things back ready for the next check
+       startNewTransaction();
+       onSetUpInTransaction();
+
+       
+       // ===========================================================
+       //    Execute a stored Action that works, asynchronously
+       // ===========================================================
+       action = createWorkingSleepAction();
+       this.actionService.saveAction(this.nodeRef, action);
+       actionNode = action.getNodeRef();
+       assertNotNull(actionNode);
+       
+       assertNull(action.getExecutionStartDate());
+       assertNull(action.getExecutionEndDate());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.New, action.getExecutionStatus());
+       
+       this.actionService.executeAction(action, this.nodeRef, false, true);
+       assertNull(action.getExecutionStartDate());
+       assertNull(action.getExecutionEndDate());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Pending, action.getExecutionStatus());
+       setComplete();
+       // End the transaction. When run from a test, this call will
+       //  block until the "async" action has finished running
+       endTransaction();
+       Thread.sleep(100);
+       
+       // Check our copy
+       assertNotNull(action.getExecutionStartDate());
+       assertNotNull(action.getExecutionEndDate());
+       assertBefore(action.getExecutionStartDate(), action.getExecutionEndDate());
+       assertBefore(action.getExecutionEndDate(), new Date());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Completed, action.getExecutionStatus());
+       
+       // Now re-load and check the stored one
+       action = runtimeActionService.createAction(actionNode);
+       assertNotNull(action.getExecutionStartDate());
+       assertNotNull(action.getExecutionEndDate());
+       assertBefore(action.getExecutionStartDate(), action.getExecutionEndDate());
+       assertBefore(action.getExecutionEndDate(), new Date());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Completed, action.getExecutionStatus());
+
+       // Put things back ready for the next check
+       startNewTransaction();
+       onSetUpInTransaction();
+
+       
+       // ===========================================================
+       //    Execute a stored Action that fails, asynchronously
+       // ===========================================================
+       action = createFailingMoveAction();
+       this.actionService.saveAction(this.nodeRef, action);
+       actionNode = action.getNodeRef();
+       assertNotNull(actionNode);
+       
+       assertNull(action.getExecutionStartDate());
+       assertNull(action.getExecutionEndDate());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.New, action.getExecutionStatus());
+       
+       this.actionService.executeAction(action, this.nodeRef, false, true);
+       assertNull(action.getExecutionStartDate());
+       assertNull(action.getExecutionEndDate());
+       assertNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Pending, action.getExecutionStatus());
+       setComplete();
+       // End the transaction. When run from a test, this call will
+       //  block until the "async" action has finished running
+       endTransaction();
+       Thread.sleep(100);
+       
+       // Check our copy
+       assertNotNull(action.getExecutionStartDate());
+       assertNotNull(action.getExecutionEndDate());
+       assertBefore(action.getExecutionStartDate(), action.getExecutionEndDate());
+       assertBefore(action.getExecutionEndDate(), new Date());
+       assertNotNull(action.getExecutionFailureMessage());
+       assertEquals(ActionStatus.Failed, action.getExecutionStatus());
+       
+       // Now re-load and check the stored one
+       action = runtimeActionService.createAction(actionNode);
+       // TODO - Fix these
+//     assertNotNull(action.getExecutionStartDate());
+//     assertNotNull(action.getExecutionEndDate());
+//     assertBefore(action.getExecutionStartDate(), action.getExecutionEndDate());
+//     assertBefore(action.getExecutionEndDate(), new Date());
+//     assertNotNull(action.getExecutionFailureMessage());
+//     assertEquals(ActionStatus.Failed, action.getExecutionStatus());
+    }
+    
+    private Action createFailingMoveAction() {
+       Action failingAction = this.actionService.createAction(MoveActionExecuter.NAME);
+       failingAction.setParameterValue(MoveActionExecuter.PARAM_ASSOC_TYPE_QNAME, ContentModel.ASSOC_CHILDREN);
+       failingAction.setParameterValue(MoveActionExecuter.PARAM_ASSOC_QNAME, ContentModel.ASSOC_CHILDREN);
+       // Create a bad node ref
+       NodeRef badNodeRef = new NodeRef(this.storeRef, "123123");
+       failingAction.setParameterValue(MoveActionExecuter.PARAM_DESTINATION_FOLDER, badNodeRef);
+       
+       return failingAction;
+    }
+    private Action createWorkingSleepAction() {
+       Action workingAction = actionService.createAction(SleepActionExecuter.NAME);
+       return workingAction;
     }
     
     /**
@@ -1279,4 +1571,12 @@ public class ActionServiceImplTest extends BaseAlfrescoSpringTest
     		}
     	}
     }
+    
+    public static void assertBefore(Date before, Date after)
+    {
+       assertTrue(
+             before.toString() + " not before " + after.toString(),
+             before.getTime() <= after.getTime()
+       );
+    }
 }

source/java/org/alfresco/repo/action/AsynchronousActionExecutionQueueImpl.java

@@ -41,6 +41,7 @@ import org.alfresco.repo.transaction.TransactionListenerAdapter;
 import org.alfresco.repo.transaction.RetryingTransactionHelper.RetryingTransactionCallback;
 import org.alfresco.service.cmr.action.Action;
 import org.alfresco.service.cmr.action.ActionServiceException;
+import org.alfresco.service.cmr.action.ActionStatus;
 import org.alfresco.service.cmr.repository.InvalidNodeRefException;
 import org.alfresco.service.cmr.repository.NodeRef;
 import org.alfresco.service.cmr.repository.NodeService;
@@ -304,7 +305,7 @@ public class AsynchronousActionExecutionQueueImpl implements AsynchronousActionE
         		msg.append("Executing action ").append(action);
         		logger.debug(msg.toString());
         	}
-
+        	
         	// Queue it and do it.
         	ongoingActions.add(nodeBeingNewlyActioned);
         	threadPoolExecutor.execute(runnable);