nav[aria-label="Primary Navigation"] { padding: 0; & ul { list-style: none; width: 100%; display: flex; flex-direction: row; justify-content: start; align-items: start; gap: 30px; padding: 0; & li { margin: 0; } & ul li { list-style: none; } } }

As we transition to the new Hyland Community, some post links may be temporarily disrupted as we finalize redirects. We apologize for the inconvenience and are working to resolve this as quickly as possible. Details.

JBPM Workflow in Alfresco 4.0 fails silently @ task-create

awbf

I have an advanced JBPM workflow that I am trying to run in Alfresco 4.0.1. It runs without error in Alfresco 3.4.3 and 3.4.5.

I am able to run JBPM workflows after adding

system.workflow.engine.jbpm.enabled=true
system.workflow.engine.jbpm.definitions.visible=true‍‍

to alfresco-global.properties.

In Alfresco 4, this workflow fails "silently" after JBPM hits any "task-create" action other than the one for the start task. By "fails silently," I mean that no error messages are printed anywhere, and setting

log4j.logger.org.jbpm=debug
log4j.logger.org.alfresco.repo.workflow=debug‍‍

doesn't produce any useful information about WHY the workflow is failing.

Starting the workflow from Alfresco Share simply pops up a box informing me that the "Workflow could not be started" with no extra information.

I have another, much simpler "hello world" advanced JBPM workflow that also worked without error in 3.4.x, which works just fine in Alfresco 4.0, and it does not have any problems with task-create.

This suggests to me that the problem must lie somewhere in the first, problematic workflow, either in its process definition, its model, or the stuff it does while it runs.

First, here's a snippet of what the FAILING workflow outputs to the log file as it tries to create a task:

2012-08-03 15:09:11,258  DEBUG [context.exe.VariableContainer] [http-8081-2] update variable 'has_folders' in 'TokenVariableMap[/]' to value 'no'
 2012-08-03 15:09:11,258  DEBUG [graph.exe.Token] [http-8081-2] token[4571] is unlocked by token[4571]
 2012-08-03 15:09:11,336  DEBUG [graph.node.Decision] [http-8081-2] decision didn't select transition, taking default Transition(no_folders)
 2012-08-03 15:09:11,336  DEBUG [graph.node.Decision] [http-8081-2] decision check_folders is taking 'Transition(no_folders)'
 2012-08-03 15:09:11,336  DEBUG [graph.def.GraphElement] [http-8081-2] event 'node-leave' on 'Decision(check_folders)' for 'Token(/)'
 2012-08-03 15:09:11,336  DEBUG [graph.def.GraphElement] [http-8081-2] event 'transition' on 'Transition(no_folders)' for 'Token(/)'
 2012-08-03 15:09:11,340  DEBUG [graph.def.GraphElement] [http-8081-2] event 'node-enter' on 'TaskNode(need_folders)' for 'Token(/)'
 2012-08-03 15:09:11,345  DEBUG [graph.def.GraphElement] [http-8081-2] event 'task-create' on 'Task(docusignwf:requesting_folders)' for 'Token(/)'
 2012-08-03 15:09:11,425  DEBUG [org.jbpm.JbpmContext] [http-8081-2] closing jbpmContext org.jbpm.JbpmContext@738f23
 2012-08-03 15:09:11,425  DEBUG [jbpm.svc.Services] [http-8081-2] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@68662676
 2012-08-03 15:09:11,425  DEBUG [jbpm.svc.Services] [http-8081-2] closing service 'tx': org.jbpm.tx.TxService@a674286
 2012-08-03 15:09:11,425  DEBUG [jbpm.svc.Services] [http-8081-2] closing service 'logging': org.jbpm.logging.db.DbLoggingService@14070c0
 2012-08-03 15:09:11,425  DEBUG [jbpm.svc.Services] [http-8081-2] closing service 'authentication': org.jbpm.security.authentication.DefaultAuthenticationService@2daa4de4
 2012-08-03 15:09:11,425  DEBUG [alfresco.repo.workflow] [http-8081-2] Detached (rollback) JBPM Context from transaction 1c83f695-9336-4067-8c6a-aa58f71e48b7‍‍‍‍‍‍‍‍‍‍‍‍‍‍

By comparision, here's what the WORKING workflow prints to the log as it tries to create a task:

 2012-08-03 15:35:56,060  DEBUG [graph.def.GraphElement] [http-8081-5] event 'node-leave' on 'StartState(start)' for 'Token(/)'
 2012-08-03 15:35:56,060  DEBUG [graph.def.GraphElement] [http-8081-5] event 'transition' on 'Transition(to_hello)' for 'Token(/)'
 2012-08-03 15:35:56,064  DEBUG [graph.def.GraphElement] [http-8081-5] event 'node-enter' on 'TaskNode(hello)' for 'Token(/)'
 2012-08-03 15:35:56,068  DEBUG [graph.def.GraphElement] [http-8081-5] event 'task-create' on 'Task(hw:are_you_sure)' for 'Token(/)'
 2012-08-03 15:35:56,072  DEBUG [context.exe.VariableContainer] [http-8081-5] create variable 'bpm_percentComplete' in 'TaskInstance(hw:are_you_sure)' with value '0'
 2012-08-03 15:35:56,072  DEBUG [context.exe.VariableContainer] [http-8081-5] create variable 'bpm_status' in 'TaskInstance(hw:are_you_sure)' with value 'Not Yet Started'
 2012-08-03 15:35:56,072  DEBUG [context.exe.VariableContainer] [http-8081-5] create variable 'bpm_reassignable' in 'TaskInstance(hw:are_you_sure)' with value 'true'
 2012-08-03 15:35:56,072  DEBUG [context.exe.VariableContainer] [http-8081-5] create variable 'bpm_hiddenTransitions' in 'TaskInstance(hw:are_you_sure)' with value ''
 2012-08-03 15:35:56,072  DEBUG [context.exe.VariableContainer] [http-8081-5] create variable 'bpm_packageActionGroup' in 'TaskInstance(hw:are_you_sure)' with value ''
 2012-08-03 15:35:56,072  DEBUG [context.exe.VariableContainer] [http-8081-5] create variable 'bpm_packageItemActionGroup' in 'TaskInstance(hw:are_you_sure)' with value 'read_package_item_actions'
 2012-08-03 15:35:56,072  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-5] assigning task 'hw:are_you_sure' to 'admin'
 2012-08-03 15:35:56,072  DEBUG [graph.def.GraphElement] [http-8081-5] event 'task-assign' on 'Task(hw:are_you_sure)' for 'Token(/)'
 2012-08-03 15:35:56,072  DEBUG [graph.def.GraphElement] [http-8081-5] event 'after-signal' on 'StartState(start)' for 'Token(/)'
 2012-08-03 15:35:56,072  DEBUG [context.exe.VariableContainer] [http-8081-5] create variable 'bpm_context' in 'TokenVariableMap[/]' with value 'null'
 2012-08-03 15:35:56,072  DEBUG [jbpm.svc.Services] [http-8081-5] executing default save operations
 2012-08-03 15:35:56,074  DEBUG [svc.save.HibernateSaveOperation] [http-8081-5] saving process instance
 2012-08-03 15:35:56,074  DEBUG [svc.save.SaveLogsOperation] [http-8081-5] flushing logs to logging service.
 2012-08-03 15:35:56,093  DEBUG [svc.save.CascadeSaveOperation] [http-8081-5] cascading save of 'ProcessInstance(36b584cf-5078-4be4-91d7-c4f68613c3d2)'
 2012-08-03 15:35:56,197  DEBUG [org.jbpm.JbpmContext] [http-8081-5] closing jbpmContext org.jbpm.JbpmContext@46d3ddd8
 2012-08-03 15:35:56,197  DEBUG [jbpm.svc.Services] [http-8081-5] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@236afc22
 2012-08-03 15:35:56,197  DEBUG [jbpm.svc.Services] [http-8081-5] closing service 'tx': org.jbpm.tx.TxService@44cf2e58
 2012-08-03 15:35:56,197  DEBUG [jbpm.svc.Services] [http-8081-5] closing service 'logging': org.jbpm.logging.db.DbLoggingService@7debb6b2
 2012-08-03 15:35:56,197  DEBUG [jbpm.svc.Services] [http-8081-5] closing service 'authentication': org.jbpm.security.authentication.DefaultAuthenticationService@7e27a0b3
 2012-08-03 15:35:56,197  DEBUG [alfresco.repo.workflow] [http-8081-5] Detached (commit) JBPM Context from transaction ccf454c9-4e4a-40f9-8dc3-934a4ac0f6bd
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

The XML from the process definition of the FAILING WORKFLOW that defines the task in question:

<task-node name="need_folders">
      <task name="docusignwf:requesting_folders" swimlane="initiator" />
      <transition name="provided_folders" to="check_folders" >
         <script>
            <!– input validation; never executes because workflow terminates on task-create, above –>
         </script>
      </transition>
</task-node>‍‍‍‍‍‍‍‍

The swimlane is the first child element of the <process-definition …> element, defined thusly:

<swimlane name="initiator" />‍

And in the FAILING WORKFLOW's model, the "requesting_folders" task's type is defined:

<types>
      (…)      
      <type name="docusignwf:requesting_folders">
         <parent>bpm:workflowTask</parent>
         
         <mandatory-aspects>
            <aspect>docusignwf:provides_folders</aspect>
         </mandatory-aspects>
      </type>
      
      <type name="docusignwf:waiting_actions">
         <parent>bpm:workflowTask</parent>
      </type>
</types>‍‍‍‍‍‍‍‍‍‍‍‍‍‍

I've left the definition of another task, "waiting_actions" in there. This workflow can head to either one of those tasks (each in its own task-node), depending on what the user provides when starting it. Both of those tasks experience the same silent failure - and "waiting actions" has no input, no properties, and no aspects. To me, this suggests that there's not a problem with "requesting_folders" having aspects/requiring input.

Now, here are snippets from the SUCCESSFUL WORKFLOW. First, the process definition. This one's short enough to where I can just post the whole thing:

<?xml version="1.0" encoding="UTF-8"?>

<process-definition xmlns="urn:jbpm.org:jpdl-3.1" name="hw:helloWorld">

   <swimlane name="initiator" />

   <start-state name="start">
      <task name="hw:cant_have_no_tasks" swimlane="initiator"/>
      <transition name="to_hello" to="hello"></transition>
   </start-state>

   <task-node name="hello">
      <task name="hw:are_you_sure" swimlane="initiator" />
      <transition name="to_end1" to="end1">
         <action class="org.alfresco.repo.workflow.jbpm.AlfrescoJavaScript">
            <script>
               logger.log("Hello World.");
            </script>
         </action>
      </transition>
   </task-node>

   <end-state name="end1"></end-state>

</process-definition>‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

As you can see, the swimlane definition and task-node definition and task definition are syntactically identical to the FAILING WORKFLOW.

Now, the SUCCEEDING WORKFLOW's task type definition, from its model:

<types>
      <type name="hw:cant_have_no_tasks">
         <parent>bpm:startTask</parent>
      </type>
      
      <type name="hw:are_you_sure">
         <parent>bpm:workflowTask</parent>
      </type>
</types>‍‍‍‍‍‍‍‍‍

No parameters or anything; the user just clicks a button for the transition to advance the workflow.

I note that the FAILING WORKFLOW succeeds up until it attempts to create a task; elements from its model are referenced and used, so the model has been loaded properly, and the workflow definition, too, has been loaded properly (else I wouldn't even be able to start the workflow).

COMPLETE trace for SUCCESSFUL WORKFLOW:

 2012-08-03 15:58:21,852  DEBUG [jbpm.configuration.JbpmContextInfo] [http-8081-4] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:58:21,852  DEBUG [org.jbpm.JbpmContext] [http-8081-4] creating org.jbpm.JbpmContext@4a814c0d
 2012-08-03 15:58:21,852  DEBUG [alfresco.repo.workflow] [http-8081-4] Attached JBPM Context to transaction d437a7a6-8e63-404e-866c-3f15dc671272
 2012-08-03 15:58:21,852  DEBUG [persistence.db.DbPersistenceServiceFactory] [http-8081-4] creating persistence service
 2012-08-03 15:58:21,852  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:21,955  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:21,957  DEBUG [graph.def.GraphElement] [http-8081-4] event 'process-start' on 'ProcessDefinition(hw:helloWorld)' for 'Token(/)'
 2012-08-03 15:58:21,959  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'cancelled' in 'TokenVariableMap[/]' with value 'false'
 2012-08-03 15:58:21,961  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_package' in 'TokenVariableMap[/]' with value 'Node Type: {http://www.alfresco.org/model/bpm/1.0}package, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/system/1.0}localized, {http://www.alfresco.org/model/bpm/1.0}workflowPackage]'
 2012-08-03 15:58:21,989  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'companyhome' in 'TokenVariableMap[/]' with value 'Node Type: {http://www.alfresco.org/model/content/1.0}folder, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/application/1.0}uifacets, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/content/1.0}titled, {http://www.alfresco.org/model/system/1.0}localized]'
 2012-08-03 15:58:21,990  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'initiator' in 'TokenVariableMap[/]' with value 'Node Type: {http://www.alfresco.org/model/content/1.0}person, Node Aspects: [{http://www.alfresco.org/model/application/1.0}configurable, {http://www.alfresco.org/model/content/1.0}ownable, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/system/1.0}localized, {http://www.alfresco.org/model/content/1.0}preferences]'
 2012-08-03 15:58:21,990  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'initiatorhome' in 'TokenVariableMap[/]' with value 'Node Type: {http://www.alfresco.org/model/content/1.0}folder, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/application/1.0}uifacets, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/content/1.0}titled, {http://www.alfresco.org/model/system/1.0}localized]'
 2012-08-03 15:58:21,992  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'workflowinstanceid' in 'TokenVariableMap[/]' with value 'jbpm$5090'
 2012-08-03 15:58:22,002  DEBUG [graph.def.GraphElement] [http-8081-4] event 'task-create' on 'Task(hw:cant_have_no_tasks)' for 'Token(/)'
 2012-08-03 15:58:22,004  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_percentComplete' in 'TaskInstance(hw:cant_have_no_tasks)' with value '0'
 2012-08-03 15:58:22,004  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_status' in 'TaskInstance(hw:cant_have_no_tasks)' with value 'Not Yet Started'
 2012-08-03 15:58:22,004  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_sendEMailNotifications' in 'TaskInstance(hw:cant_have_no_tasks)' with value 'false'
 2012-08-03 15:58:22,004  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_reassignable' in 'TaskInstance(hw:cant_have_no_tasks)' with value 'true'
 2012-08-03 15:58:22,004  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_hiddenTransitions' in 'TaskInstance(hw:cant_have_no_tasks)' with value ''
 2012-08-03 15:58:22,004  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_workflowPriority' in 'TaskInstance(hw:cant_have_no_tasks)' with value '2'
 2012-08-03 15:58:22,004  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_packageActionGroup' in 'TaskInstance(hw:cant_have_no_tasks)' with value 'add_package_item_actions'
 2012-08-03 15:58:22,004  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_packageItemActionGroup' in 'TaskInstance(hw:cant_have_no_tasks)' with value 'start_package_item_actions'
 2012-08-03 15:58:22,008  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] assigning task 'hw:cant_have_no_tasks' to 'admin'
 2012-08-03 15:58:22,008  DEBUG [graph.def.GraphElement] [http-8081-4] event 'task-assign' on 'Task(hw:cant_have_no_tasks)' for 'Token(/)'
 2012-08-03 15:58:22,008  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_percentComplete' in 'TaskInstance(hw:cant_have_no_tasks)' to value '0'
 2012-08-03 15:58:22,008  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_sendEMailNotifications' in 'TaskInstance(hw:cant_have_no_tasks)' to value 'false'
 2012-08-03 15:58:22,008  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_status' in 'TaskInstance(hw:cant_have_no_tasks)' to value 'Not Yet Started'
 2012-08-03 15:58:22,010  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_package' in 'TaskInstance(hw:cant_have_no_tasks)' with value 'Node Type: {http://www.alfresco.org/model/bpm/1.0}package, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/system/1.0}localized, {http://www.alfresco.org/model/bpm/1.0}workflowPackage]'
 2012-08-03 15:58:22,010  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_workflowDescription' in 'TaskInstance(hw:cant_have_no_tasks)' with value ''
 2012-08-03 15:58:22,010  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_workflowPriority' in 'TaskInstance(hw:cant_have_no_tasks)' to value '2'
 2012-08-03 15:58:22,010  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_workflowDueDate' in 'TaskInstance(hw:cant_have_no_tasks)' with value 'null'
 2012-08-03 15:58:22,010  DEBUG [jbpm.svc.Services] [http-8081-4] executing default save operations
 2012-08-03 15:58:22,010  DEBUG [svc.save.HibernateSaveOperation] [http-8081-4] saving process instance
 2012-08-03 15:58:22,010  DEBUG [svc.save.SaveLogsOperation] [http-8081-4] flushing logs to logging service.
 2012-08-03 15:58:22,030  DEBUG [svc.save.CascadeSaveOperation] [http-8081-4] cascading save of 'ProcessInstance(b88e6c2e-900c-4702-89d7-743e1f991a5e)'
 2012-08-03 15:58:22,057  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:22,149  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:22,149  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_status' in 'TaskInstance(hw:cant_have_no_tasks)' to value 'Completed'
 2012-08-03 15:58:22,149  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_outcome' in 'TaskInstance(hw:cant_have_no_tasks)' with value 'to_hello'
 2012-08-03 15:58:22,149  DEBUG [graph.def.GraphElement] [http-8081-4] event 'task-end' on 'Task(hw:cant_have_no_tasks)' for 'Token(/)'
 2012-08-03 15:58:22,149  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_workflowDueDate' from task 'hw:cant_have_no_tasks' to process variables
 2012-08-03 15:58:22,149  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_workflowDueDate' in 'TokenVariableMap[/]' with value 'null'
 2012-08-03 15:58:22,149  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_workflowDescription' from task 'hw:cant_have_no_tasks' to process variables
 2012-08-03 15:58:22,149  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_workflowDescription' in 'TokenVariableMap[/]' with value ''
 2012-08-03 15:58:22,149  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_percentComplete' from task 'hw:cant_have_no_tasks' to process variables
 2012-08-03 15:58:22,149  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_percentComplete' in 'TokenVariableMap[/]' with value '0'
 2012-08-03 15:58:22,151  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_status' from task 'hw:cant_have_no_tasks' to process variables
 2012-08-03 15:58:22,151  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_status' in 'TokenVariableMap[/]' with value 'Completed'
 2012-08-03 15:58:22,151  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_sendEMailNotifications' from task 'hw:cant_have_no_tasks' to process variables
 2012-08-03 15:58:22,151  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_sendEMailNotifications' in 'TokenVariableMap[/]' with value 'false'
 2012-08-03 15:58:22,151  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_packageActionGroup' from task 'hw:cant_have_no_tasks' to process variables
 2012-08-03 15:58:22,151  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_packageActionGroup' in 'TokenVariableMap[/]' with value 'add_package_item_actions'
 2012-08-03 15:58:22,151  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_hiddenTransitions' from task 'hw:cant_have_no_tasks' to process variables
 2012-08-03 15:58:22,151  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_hiddenTransitions' in 'TokenVariableMap[/]' with value ''
 2012-08-03 15:58:22,151  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_package' from task 'hw:cant_have_no_tasks' to process variables
 2012-08-03 15:58:22,151  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_package' in 'TokenVariableMap[/]' to value 'Node Type: {http://www.alfresco.org/model/bpm/1.0}package, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/system/1.0}localized, {http://www.alfresco.org/model/bpm/1.0}workflowPackage]'
 2012-08-03 15:58:22,151  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_packageItemActionGroup' from task 'hw:cant_have_no_tasks' to process variables
 2012-08-03 15:58:22,151  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_packageItemActionGroup' in 'TokenVariableMap[/]' with value 'start_package_item_actions'
 2012-08-03 15:58:22,151  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_outcome' from task 'hw:cant_have_no_tasks' to process variables
 2012-08-03 15:58:22,151  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_outcome' in 'TokenVariableMap[/]' with value 'to_hello'
 2012-08-03 15:58:22,151  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_workflowPriority' from task 'hw:cant_have_no_tasks' to process variables
 2012-08-03 15:58:22,151  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_workflowPriority' in 'TokenVariableMap[/]' with value '2'
 2012-08-03 15:58:22,151  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_reassignable' from task 'hw:cant_have_no_tasks' to process variables
 2012-08-03 15:58:22,151  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_reassignable' in 'TokenVariableMap[/]' with value 'true'
 2012-08-03 15:58:22,151  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] completion of task 'hw:cant_have_no_tasks' results in taking the default transition
 2012-08-03 15:58:22,153  DEBUG [graph.def.GraphElement] [http-8081-4] event 'before-signal' on 'StartState(start)' for 'Token(/)'
 2012-08-03 15:58:22,153  DEBUG [graph.def.GraphElement] [http-8081-4] event 'node-leave' on 'StartState(start)' for 'Token(/)'
 2012-08-03 15:58:22,153  DEBUG [graph.def.GraphElement] [http-8081-4] event 'transition' on 'Transition(to_hello)' for 'Token(/)'
 2012-08-03 15:58:22,155  DEBUG [graph.def.GraphElement] [http-8081-4] event 'node-enter' on 'TaskNode(hello)' for 'Token(/)'
 2012-08-03 15:58:22,190  DEBUG [graph.def.GraphElement] [http-8081-4] event 'task-create' on 'Task(hw:are_you_sure)' for 'Token(/)'
 2012-08-03 15:58:22,194  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_percentComplete' in 'TaskInstance(hw:are_you_sure)' with value '0'
 2012-08-03 15:58:22,196  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_status' in 'TaskInstance(hw:are_you_sure)' with value 'Not Yet Started'
 2012-08-03 15:58:22,196  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_reassignable' in 'TaskInstance(hw:are_you_sure)' with value 'true'
 2012-08-03 15:58:22,196  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_hiddenTransitions' in 'TaskInstance(hw:are_you_sure)' with value ''
 2012-08-03 15:58:22,196  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_packageActionGroup' in 'TaskInstance(hw:are_you_sure)' with value ''
 2012-08-03 15:58:22,196  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_packageItemActionGroup' in 'TaskInstance(hw:are_you_sure)' with value 'read_package_item_actions'
 2012-08-03 15:58:22,196  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] assigning task 'hw:are_you_sure' to 'admin'
 2012-08-03 15:58:22,196  DEBUG [graph.def.GraphElement] [http-8081-4] event 'task-assign' on 'Task(hw:are_you_sure)' for 'Token(/)'
 2012-08-03 15:58:22,196  DEBUG [graph.def.GraphElement] [http-8081-4] event 'after-signal' on 'StartState(start)' for 'Token(/)'
 2012-08-03 15:58:22,196  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_context' in 'TokenVariableMap[/]' with value 'null'
 2012-08-03 15:58:22,196  DEBUG [jbpm.svc.Services] [http-8081-4] executing default save operations
 2012-08-03 15:58:22,196  DEBUG [svc.save.HibernateSaveOperation] [http-8081-4] saving process instance
 2012-08-03 15:58:22,196  DEBUG [svc.save.SaveLogsOperation] [http-8081-4] flushing logs to logging service.
 2012-08-03 15:58:22,219  DEBUG [svc.save.CascadeSaveOperation] [http-8081-4] cascading save of 'ProcessInstance(b88e6c2e-900c-4702-89d7-743e1f991a5e)'
 2012-08-03 15:58:22,315  DEBUG [org.jbpm.JbpmContext] [http-8081-4] closing jbpmContext org.jbpm.JbpmContext@4a814c0d
 2012-08-03 15:58:22,315  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@33597ad5
 2012-08-03 15:58:22,315  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'tx': org.jbpm.tx.TxService@378f5049
 2012-08-03 15:58:22,315  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'logging': org.jbpm.logging.db.DbLoggingService@21e0051e
 2012-08-03 15:58:22,315  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'authentication': org.jbpm.security.authentication.DefaultAuthenticationService@7a7005f1
 2012-08-03 15:58:22,315  DEBUG [alfresco.repo.workflow] [http-8081-4] Detached (commit) JBPM Context from transaction d437a7a6-8e63-404e-866c-3f15dc671272
 2012-08-03 15:58:22,504  DEBUG [jbpm.configuration.JbpmContextInfo] [http-8081-4] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:58:22,504  DEBUG [org.jbpm.JbpmContext] [http-8081-4] creating org.jbpm.JbpmContext@2c8446f7
 2012-08-03 15:58:22,504  DEBUG [alfresco.repo.workflow] [http-8081-4] Attached JBPM Context to transaction ee96cf7b-651c-48ed-87b9-3b9ec317d3d5
 2012-08-03 15:58:22,504  DEBUG [persistence.db.DbPersistenceServiceFactory] [http-8081-4] creating persistence service
 2012-08-03 15:58:22,504  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:22,526  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:22,551  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:22,606  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:22,670  DEBUG [org.jbpm.JbpmContext] [http-8081-4] closing jbpmContext org.jbpm.JbpmContext@2c8446f7
 2012-08-03 15:58:22,670  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@6df5044a
 2012-08-03 15:58:22,670  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'tx': org.jbpm.tx.TxService@70ecceab
 2012-08-03 15:58:22,670  DEBUG [alfresco.repo.workflow] [http-8081-4] Detached (commit) JBPM Context from transaction ee96cf7b-651c-48ed-87b9-3b9ec317d3d5
 2012-08-03 15:58:23,203  DEBUG [jbpm.configuration.JbpmContextInfo] [http-8081-4] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:58:23,203  DEBUG [org.jbpm.JbpmContext] [http-8081-4] creating org.jbpm.JbpmContext@32ddb0c
 2012-08-03 15:58:23,203  DEBUG [alfresco.repo.workflow] [http-8081-4] Attached JBPM Context to transaction 6cdc2ced-c63a-422a-9724-1feaa2a0d455
 2012-08-03 15:58:23,203  DEBUG [persistence.db.DbPersistenceServiceFactory] [http-8081-4] creating persistence service
 2012-08-03 15:58:23,203  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:23,223  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:23,233  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:23,248  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:23,289  DEBUG [org.jbpm.JbpmContext] [http-8081-4] closing jbpmContext org.jbpm.JbpmContext@32ddb0c
 2012-08-03 15:58:23,289  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@2e6ede78
 2012-08-03 15:58:23,289  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'tx': org.jbpm.tx.TxService@70cfb018
 2012-08-03 15:58:23,289  DEBUG [alfresco.repo.workflow] [http-8081-4] Detached (commit) JBPM Context from transaction 6cdc2ced-c63a-422a-9724-1feaa2a0d455
 2012-08-03 15:58:26,926  DEBUG [jbpm.configuration.JbpmContextInfo] [http-8081-1] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:58:26,926  DEBUG [org.jbpm.JbpmContext] [http-8081-1] creating org.jbpm.JbpmContext@14c6f844
 2012-08-03 15:58:26,926  DEBUG [alfresco.repo.workflow] [http-8081-1] Attached JBPM Context to transaction 317df49c-1149-4bc5-be83-ad1d87b07fe2
 2012-08-03 15:58:26,926  DEBUG [persistence.db.DbPersistenceServiceFactory] [http-8081-1] creating persistence service
 2012-08-03 15:58:26,926  DEBUG [persistence.db.DbPersistenceService] [http-8081-1] injecting a session disables transaction
 2012-08-03 15:58:26,978  DEBUG [persistence.db.DbPersistenceService] [http-8081-1] injecting a session disables transaction
 2012-08-03 15:58:26,982  DEBUG [persistence.db.DbPersistenceService] [http-8081-1] injecting a session disables transaction
 2012-08-03 15:58:26,985  DEBUG [persistence.db.DbPersistenceService] [http-8081-1] injecting a session disables transaction
 2012-08-03 15:58:26,986  DEBUG [persistence.db.DbPersistenceService] [http-8081-1] injecting a session disables transaction
 2012-08-03 15:58:26,987  DEBUG [persistence.db.DbPersistenceService] [http-8081-1] injecting a session disables transaction
 2012-08-03 15:58:27,015  DEBUG [org.jbpm.JbpmContext] [http-8081-1] closing jbpmContext org.jbpm.JbpmContext@14c6f844
 2012-08-03 15:58:27,015  DEBUG [jbpm.svc.Services] [http-8081-1] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@1365e36d
 2012-08-03 15:58:27,015  DEBUG [jbpm.svc.Services] [http-8081-1] closing service 'tx': org.jbpm.tx.TxService@636130e
 2012-08-03 15:58:27,015  DEBUG [alfresco.repo.workflow] [http-8081-1] Detached (commit) JBPM Context from transaction 317df49c-1149-4bc5-be83-ad1d87b07fe2
 2012-08-03 15:58:28,533  DEBUG [jbpm.configuration.JbpmContextInfo] [http-8081-5] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:58:28,534  DEBUG [org.jbpm.JbpmContext] [http-8081-5] creating org.jbpm.JbpmContext@6fc2a5bf
 2012-08-03 15:58:28,534  DEBUG [alfresco.repo.workflow] [http-8081-5] Attached JBPM Context to transaction 57d77d5e-7b77-4e44-ab22-1ad2b6ee66ec
 2012-08-03 15:58:28,534  DEBUG [persistence.db.DbPersistenceServiceFactory] [http-8081-5] creating persistence service
 2012-08-03 15:58:28,534  DEBUG [persistence.db.DbPersistenceService] [http-8081-5] injecting a session disables transaction
 2012-08-03 15:58:28,560  DEBUG [persistence.db.DbPersistenceService] [http-8081-5] injecting a session disables transaction
 2012-08-03 15:58:28,561  DEBUG [persistence.db.DbPersistenceService] [http-8081-5] injecting a session disables transaction
 2012-08-03 15:58:28,562  DEBUG [persistence.db.DbPersistenceService] [http-8081-5] injecting a session disables transaction
 2012-08-03 15:58:28,563  DEBUG [persistence.db.DbPersistenceService] [http-8081-5] injecting a session disables transaction
 2012-08-03 15:58:28,595  DEBUG [org.jbpm.JbpmContext] [http-8081-5] closing jbpmContext org.jbpm.JbpmContext@6fc2a5bf
 2012-08-03 15:58:28,595  DEBUG [jbpm.svc.Services] [http-8081-5] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@7a200513
 2012-08-03 15:58:28,595  DEBUG [jbpm.svc.Services] [http-8081-5] closing service 'tx': org.jbpm.tx.TxService@4c2d6108
 2012-08-03 15:58:28,595  DEBUG [alfresco.repo.workflow] [http-8081-5] Detached (commit) JBPM Context from transaction 57d77d5e-7b77-4e44-ab22-1ad2b6ee66ec
 2012-08-03 15:58:28,623  DEBUG [jbpm.configuration.JbpmContextInfo] [http-8081-5] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:58:28,623  DEBUG [org.jbpm.JbpmContext] [http-8081-5] creating org.jbpm.JbpmContext@373d7b4a
 2012-08-03 15:58:28,623  DEBUG [alfresco.repo.workflow] [http-8081-5] Attached JBPM Context to transaction 96d8b5ab-98e6-42f6-b9d0-d53102480083
 2012-08-03 15:58:28,623  DEBUG [persistence.db.DbPersistenceServiceFactory] [http-8081-5] creating persistence service
 2012-08-03 15:58:28,623  DEBUG [persistence.db.DbPersistenceService] [http-8081-5] injecting a session disables transaction
 2012-08-03 15:58:28,691  DEBUG [persistence.db.DbPersistenceService] [http-8081-5] injecting a session disables transaction
 2012-08-03 15:58:28,719  DEBUG [org.jbpm.JbpmContext] [http-8081-5] closing jbpmContext org.jbpm.JbpmContext@373d7b4a
 2012-08-03 15:58:28,719  DEBUG [jbpm.svc.Services] [http-8081-5] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@5d8aef3b
 2012-08-03 15:58:28,719  DEBUG [jbpm.svc.Services] [http-8081-5] closing service 'tx': org.jbpm.tx.TxService@4c603a77
 2012-08-03 15:58:28,719  DEBUG [alfresco.repo.workflow] [http-8081-5] Detached (commit) JBPM Context from transaction 96d8b5ab-98e6-42f6-b9d0-d53102480083
 2012-08-03 15:58:29,329  DEBUG [jbpm.configuration.JbpmContextInfo] [http-8081-6] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:58:29,329  DEBUG [org.jbpm.JbpmContext] [http-8081-6] creating org.jbpm.JbpmContext@84a6af2
 2012-08-03 15:58:29,329  DEBUG [alfresco.repo.workflow] [http-8081-6] Attached JBPM Context to transaction c6f101ec-68e1-40aa-9ec8-39bb74d98323
 2012-08-03 15:58:29,329  DEBUG [persistence.db.DbPersistenceServiceFactory] [http-8081-6] creating persistence service
 2012-08-03 15:58:29,329  DEBUG [persistence.db.DbPersistenceService] [http-8081-6] injecting a session disables transaction
 2012-08-03 15:58:29,479  DEBUG [persistence.db.DbPersistenceService] [http-8081-6] injecting a session disables transaction
 2012-08-03 15:58:29,481  DEBUG [persistence.db.DbPersistenceService] [http-8081-6] injecting a session disables transaction
 2012-08-03 15:58:29,481  DEBUG [persistence.db.DbPersistenceService] [http-8081-6] injecting a session disables transaction
 2012-08-03 15:58:29,483  DEBUG [persistence.db.DbPersistenceService] [http-8081-6] injecting a session disables transaction
 2012-08-03 15:58:29,499  DEBUG [org.jbpm.JbpmContext] [http-8081-6] closing jbpmContext org.jbpm.JbpmContext@84a6af2
 2012-08-03 15:58:29,499  DEBUG [jbpm.svc.Services] [http-8081-6] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@163b66f7
 2012-08-03 15:58:29,499  DEBUG [jbpm.svc.Services] [http-8081-6] closing service 'tx': org.jbpm.tx.TxService@15e4ed88
 2012-08-03 15:58:29,499  DEBUG [alfresco.repo.workflow] [http-8081-6] Detached (commit) JBPM Context from transaction c6f101ec-68e1-40aa-9ec8-39bb74d98323
 2012-08-03 15:58:31,167  DEBUG [jbpm.configuration.JbpmContextInfo] [http-8081-4] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:58:31,169  DEBUG [org.jbpm.JbpmContext] [http-8081-4] creating org.jbpm.JbpmContext@ed979d0
 2012-08-03 15:58:31,169  DEBUG [alfresco.repo.workflow] [http-8081-4] Attached JBPM Context to transaction 5289cdc5-05c7-4189-9bc9-eeee2412b4f5
 2012-08-03 15:58:31,169  DEBUG [persistence.db.DbPersistenceServiceFactory] [http-8081-4] creating persistence service
 2012-08-03 15:58:31,169  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:31,315  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:31,344  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:31,348  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:31,350  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:31,354  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:31,354  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_percentComplete' in 'TaskInstance(hw:are_you_sure)' to value '0'
 2012-08-03 15:58:31,354  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_status' in 'TaskInstance(hw:are_you_sure)' to value 'Not Yet Started'
 2012-08-03 15:58:31,360  DEBUG [jbpm.svc.Services] [http-8081-4] executing default save operations
 2012-08-03 15:58:31,360  DEBUG [svc.save.HibernateSaveOperation] [http-8081-4] saving process instance
 2012-08-03 15:58:31,360  DEBUG [svc.save.SaveLogsOperation] [http-8081-4] flushing logs to logging service.
 2012-08-03 15:58:31,360  DEBUG [svc.save.CascadeSaveOperation] [http-8081-4] cascading save of 'ProcessInstance(b88e6c2e-900c-4702-89d7-743e1f991a5e)'
 2012-08-03 15:58:31,362  DEBUG [persistence.db.DbPersistenceService] [http-8081-4] injecting a session disables transaction
 2012-08-03 15:58:31,362  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_status' in 'TaskInstance(hw:are_you_sure)' to value 'Completed'
 2012-08-03 15:58:31,362  DEBUG [context.exe.VariableContainer] [http-8081-4] create variable 'bpm_outcome' in 'TaskInstance(hw:are_you_sure)' with value 'to_end1'
 2012-08-03 15:58:31,362  DEBUG [graph.def.GraphElement] [http-8081-4] event 'task-end' on 'Task(hw:are_you_sure)' for 'Token(/)'
 2012-08-03 15:58:31,374  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_percentComplete' from task 'hw:are_you_sure' to process variables
 2012-08-03 15:58:31,374  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_percentComplete' in 'TokenVariableMap[/]' to value '0'
 2012-08-03 15:58:31,374  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_status' from task 'hw:are_you_sure' to process variables
 2012-08-03 15:58:31,374  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_status' in 'TokenVariableMap[/]' to value 'Completed'
 2012-08-03 15:58:31,374  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_packageActionGroup' from task 'hw:are_you_sure' to process variables
 2012-08-03 15:58:31,374  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_packageActionGroup' in 'TokenVariableMap[/]' to value ''
 2012-08-03 15:58:31,374  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_hiddenTransitions' from task 'hw:are_you_sure' to process variables
 2012-08-03 15:58:31,374  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_hiddenTransitions' in 'TokenVariableMap[/]' to value ''
 2012-08-03 15:58:31,374  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_packageItemActionGroup' from task 'hw:are_you_sure' to process variables
 2012-08-03 15:58:31,374  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_packageItemActionGroup' in 'TokenVariableMap[/]' to value 'read_package_item_actions'
 2012-08-03 15:58:31,374  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_outcome' from task 'hw:are_you_sure' to process variables
 2012-08-03 15:58:31,374  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_outcome' in 'TokenVariableMap[/]' to value 'to_end1'
 2012-08-03 15:58:31,374  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] flushing variable 'bpm_reassignable' from task 'hw:are_you_sure' to process variables
 2012-08-03 15:58:31,374  DEBUG [context.exe.VariableContainer] [http-8081-4] update variable 'bpm_reassignable' in 'TokenVariableMap[/]' to value 'true'
 2012-08-03 15:58:31,378  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-4] completion of task 'hw:are_you_sure' results in taking transition 'Transition(to_end1)'
 2012-08-03 15:58:31,380  DEBUG [graph.def.GraphElement] [http-8081-4] event 'before-signal' on 'TaskNode(hello)' for 'Token(/)'
 2012-08-03 15:58:31,380  DEBUG [graph.def.GraphElement] [http-8081-4] event 'node-leave' on 'TaskNode(hello)' for 'Token(/)'
 2012-08-03 15:58:31,380  DEBUG [graph.def.GraphElement] [http-8081-4] event 'transition' on 'Transition(to_end1)' for 'Token(/)'
 2012-08-03 15:58:31,381  DEBUG [graph.def.GraphElement] [http-8081-4] executing action 'Action(5f7808af)'
 2012-08-03 15:58:31,381  DEBUG [graph.exe.Token] [http-8081-4] token[5091] is locked by token[5091]
 2012-08-03 15:58:31,391  DEBUG [graph.exe.Token] [http-8081-4] token[5091] is unlocked by token[5091]
 2012-08-03 15:58:31,391  DEBUG [graph.def.GraphElement] [http-8081-4] event 'node-enter' on 'EndState(end1)' for 'Token(/)'
 2012-08-03 15:58:31,399  DEBUG [graph.def.GraphElement] [http-8081-4] event 'process-end' on 'ProcessDefinition(hw:helloWorld)' for 'Token(/)'
 2012-08-03 15:58:31,399  DEBUG [msg.db.DbMessageService] [http-8081-4] saved job[5220, org.jbpm.job.CleanUpProcessJob]
 2012-08-03 15:58:31,415  DEBUG [graph.def.GraphElement] [http-8081-4] event 'after-signal' on 'TaskNode(hello)' for 'Token(/)'
 2012-08-03 15:58:31,415  DEBUG [jbpm.svc.Services] [http-8081-4] executing default save operations
 2012-08-03 15:58:31,415  DEBUG [svc.save.HibernateSaveOperation] [http-8081-4] saving process instance
 2012-08-03 15:58:31,415  DEBUG [svc.save.SaveLogsOperation] [http-8081-4] flushing logs to logging service.
 2012-08-03 15:58:31,438  DEBUG [svc.save.CascadeSaveOperation] [http-8081-4] cascading save of 'ProcessInstance(b88e6c2e-900c-4702-89d7-743e1f991a5e)'
 2012-08-03 15:58:31,485  DEBUG [org.jbpm.JbpmContext] [http-8081-4] closing jbpmContext org.jbpm.JbpmContext@ed979d0
 2012-08-03 15:58:31,485  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@4d418fe4
 2012-08-03 15:58:31,485  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'tx': org.jbpm.tx.TxService@b4de95c
 2012-08-03 15:58:31,485  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'message': org.jbpm.msg.db.DbMessageService@28139cd0
 2012-08-03 15:58:31,487  DEBUG [msg.db.DbMessageService] [http-8081-4] messages were produced, job executor will be signalled
 2012-08-03 15:58:31,487  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'logging': org.jbpm.logging.db.DbLoggingService@1f9c303e
 2012-08-03 15:58:31,487  DEBUG [jbpm.svc.Services] [http-8081-4] closing service 'authentication': org.jbpm.security.authentication.DefaultAuthenticationService@472346a8
 2012-08-03 15:58:31,487  DEBUG [alfresco.repo.workflow] [http-8081-4] Detached (commit) JBPM Context from transaction 5289cdc5-05c7-4189-9bc9-eeee2412b4f5
 2012-08-03 15:58:31,499  DEBUG [job.executor.JobExecutorThread] [AlfrescoJbpmJobExecutor:10.2.1.52:1] acquiring jobs for execution…
 2012-08-03 15:58:31,499  DEBUG [jbpm.configuration.JbpmContextInfo] [AlfrescoJbpmJobExecutor:10.2.1.52:1] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:58:31,501  DEBUG [org.jbpm.JbpmContext] [AlfrescoJbpmJobExecutor:10.2.1.52:1] creating org.jbpm.JbpmContext@5cf3e414
 2012-08-03 15:58:31,501  DEBUG [persistence.db.DbPersistenceServiceFactory] [AlfrescoJbpmJobExecutor:10.2.1.52:1] creating persistence service
 2012-08-03 15:58:31,501  DEBUG [persistence.db.DbPersistenceService] [AlfrescoJbpmJobExecutor:10.2.1.52:1] using current hibernate session
 2012-08-03 15:58:31,501  DEBUG [job.executor.JobExecutorThread] [AlfrescoJbpmJobExecutor:10.2.1.52:1] querying for acquirable job…
 2012-08-03 15:58:31,534  DEBUG [job.executor.JobExecutorThread] [AlfrescoJbpmJobExecutor:10.2.1.52:1] trying to obtain lock on job[5220]
 2012-08-03 15:58:31,534  DEBUG [org.jbpm.JbpmContext] [AlfrescoJbpmJobExecutor:10.2.1.52:1] closing jbpmContext org.jbpm.JbpmContext@5cf3e414
 2012-08-03 15:58:31,534  DEBUG [jbpm.svc.Services] [AlfrescoJbpmJobExecutor:10.2.1.52:1] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@6b958bd3
 2012-08-03 15:58:31,534  DEBUG [jbpm.svc.Services] [AlfrescoJbpmJobExecutor:10.2.1.52:1] closing service 'tx': org.jbpm.tx.TxService@270f00d3
 2012-08-03 15:58:31,534  DEBUG [job.executor.JobExecutorThread] [AlfrescoJbpmJobExecutor:10.2.1.52:1] obtained lock on jobs: [job[5220]]
 2012-08-03 15:58:31,551  DEBUG [workflow.jbpm.AlfrescoJobExecutorThread] [AlfrescoJbpmJobExecutor:10.2.1.52:1] acquired 1 job
 2012-08-03 15:58:31,555  DEBUG [jbpm.configuration.JbpmContextInfo] [AlfrescoJbpmJobExecutor:10.2.1.52:1] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:58:31,555  DEBUG [org.jbpm.JbpmContext] [AlfrescoJbpmJobExecutor:10.2.1.52:1] creating org.jbpm.JbpmContext@49ff30ad
 2012-08-03 15:58:31,555  DEBUG [persistence.db.DbPersistenceServiceFactory] [AlfrescoJbpmJobExecutor:10.2.1.52:1] creating persistence service
 2012-08-03 15:58:31,555  DEBUG [persistence.db.DbPersistenceService] [AlfrescoJbpmJobExecutor:10.2.1.52:1] using current hibernate session
 2012-08-03 15:58:31,559  DEBUG [jbpm.db.JobSession] [AlfrescoJbpmJobExecutor:10.2.1.52:1] deleting timers for ProcessInstance(b88e6c2e-900c-4702-89d7-743e1f991a5e)
 2012-08-03 15:58:31,563  DEBUG [jbpm.db.JobSession] [AlfrescoJbpmJobExecutor:10.2.1.52:1] 0 remaining timers for ProcessInstance(b88e6c2e-900c-4702-89d7-743e1f991a5e) were deleted
 2012-08-03 15:58:31,563  DEBUG [jbpm.db.JobSession] [AlfrescoJbpmJobExecutor:10.2.1.52:1] deleting execute-node-jobs for ProcessInstance(b88e6c2e-900c-4702-89d7-743e1f991a5e)
 2012-08-03 15:58:31,563  DEBUG [jbpm.db.JobSession] [AlfrescoJbpmJobExecutor:10.2.1.52:1] 0 remaining execute-node-jobs for ProcessInstance(b88e6c2e-900c-4702-89d7-743e1f991a5e) were deleted
 2012-08-03 15:58:31,563  DEBUG [workflow.jbpm.AlfrescoJobExecutorThread] [AlfrescoJbpmJobExecutor:10.2.1.52:1] executed and deleted: job[5220]
 2012-08-03 15:58:31,563  DEBUG [org.jbpm.JbpmContext] [AlfrescoJbpmJobExecutor:10.2.1.52:1] closing jbpmContext org.jbpm.JbpmContext@49ff30ad
 2012-08-03 15:58:31,563  DEBUG [jbpm.svc.Services] [AlfrescoJbpmJobExecutor:10.2.1.52:1] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@1d8268bd
 2012-08-03 15:58:31,563  DEBUG [jbpm.svc.Services] [AlfrescoJbpmJobExecutor:10.2.1.52:1] closing service 'tx': org.jbpm.tx.TxService@5caa5f6d
 2012-08-03 15:58:31,565  DEBUG [jbpm.svc.Services] [AlfrescoJbpmJobExecutor:10.2.1.52:1] closing service 'scheduler': org.jbpm.scheduler.db.DbSchedulerService@355f1ca2
 2012-08-03 15:58:31,678  DEBUG [job.executor.JobExecutorThread] [AlfrescoJbpmJobExecutor:10.2.1.52:1] acquiring jobs for execution…
 2012-08-03 15:58:31,678  DEBUG [jbpm.configuration.JbpmContextInfo] [AlfrescoJbpmJobExecutor:10.2.1.52:1] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:58:31,678  DEBUG [org.jbpm.JbpmContext] [AlfrescoJbpmJobExecutor:10.2.1.52:1] creating org.jbpm.JbpmContext@4fe08d9
 2012-08-03 15:58:31,678  DEBUG [persistence.db.DbPersistenceServiceFactory] [AlfrescoJbpmJobExecutor:10.2.1.52:1] creating persistence service
 2012-08-03 15:58:31,678  DEBUG [persistence.db.DbPersistenceService] [AlfrescoJbpmJobExecutor:10.2.1.52:1] using current hibernate session
 2012-08-03 15:58:31,678  DEBUG [job.executor.JobExecutorThread] [AlfrescoJbpmJobExecutor:10.2.1.52:1] querying for acquirable job…
 2012-08-03 15:58:31,991  DEBUG [jbpm.configuration.JbpmContextInfo] [http-8081-6] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:58:31,991  DEBUG [org.jbpm.JbpmContext] [http-8081-6] creating org.jbpm.JbpmContext@7ddaca36
 2012-08-03 15:58:31,991  DEBUG [alfresco.repo.workflow] [http-8081-6] Attached JBPM Context to transaction 5227592b-e5f7-4d33-b449-a653db566777
 2012-08-03 15:58:31,991  DEBUG [persistence.db.DbPersistenceServiceFactory] [http-8081-6] creating persistence service
 2012-08-03 15:58:31,991  DEBUG [persistence.db.DbPersistenceService] [http-8081-6] injecting a session disables transaction
 2012-08-03 15:58:32,012  DEBUG [job.executor.JobExecutorThread] [AlfrescoJbpmJobExecutor:10.2.1.52:1] no acquirable jobs in job table
 2012-08-03 15:58:32,012  DEBUG [org.jbpm.JbpmContext] [AlfrescoJbpmJobExecutor:10.2.1.52:1] closing jbpmContext org.jbpm.JbpmContext@4fe08d9
 2012-08-03 15:58:32,012  DEBUG [jbpm.svc.Services] [AlfrescoJbpmJobExecutor:10.2.1.52:1] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@1f0a6709
 2012-08-03 15:58:32,012  DEBUG [jbpm.svc.Services] [AlfrescoJbpmJobExecutor:10.2.1.52:1] closing service 'tx': org.jbpm.tx.TxService@63f28fca
 2012-08-03 15:58:32,012  DEBUG [job.executor.JobExecutorThread] [AlfrescoJbpmJobExecutor:10.2.1.52:1] obtained lock on jobs: []
 2012-08-03 15:58:32,014  DEBUG [persistence.db.DbPersistenceService] [http-8081-6] injecting a session disables transaction
 2012-08-03 15:58:32,032  DEBUG [org.jbpm.JbpmContext] [http-8081-6] closing jbpmContext org.jbpm.JbpmContext@7ddaca36
 2012-08-03 15:58:32,032  DEBUG [jbpm.svc.Services] [http-8081-6] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@4d8493de
 2012-08-03 15:58:32,032  DEBUG [jbpm.svc.Services] [http-8081-6] closing service 'tx': org.jbpm.tx.TxService@3b07fb94
 2012-08-03 15:58:32,032  DEBUG [alfresco.repo.workflow] [http-8081-6] Detached (commit) JBPM Context from transaction 5227592b-e5f7-4d33-b449-a653db566777‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

COMPLETE trace for FAILING WORKFLOW:

 2012-08-03 15:59:49,449  DEBUG [jbpm.configuration.JbpmContextInfo] [http-8081-6] creating jbpm context with service factories '[message, tx, scheduler, authentication, persistence, logging]'
 2012-08-03 15:59:49,449  DEBUG [org.jbpm.JbpmContext] [http-8081-6] creating org.jbpm.JbpmContext@53ec452c
 2012-08-03 15:59:49,449  DEBUG [alfresco.repo.workflow] [http-8081-6] Attached JBPM Context to transaction 5bc0a306-603c-44f9-ae65-5641cacd2eab
 2012-08-03 15:59:49,449  DEBUG [persistence.db.DbPersistenceServiceFactory] [http-8081-6] creating persistence service
 2012-08-03 15:59:49,449  DEBUG [persistence.db.DbPersistenceService] [http-8081-6] injecting a session disables transaction
 2012-08-03 15:59:49,554  DEBUG [persistence.db.DbPersistenceService] [http-8081-6] injecting a session disables transaction
 2012-08-03 15:59:49,556  DEBUG [graph.def.GraphElement] [http-8081-6] event 'process-start' on 'ProcessDefinition(docusignwf:basic_workflow)' for 'Token(/)'
 2012-08-03 15:59:49,558  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'cancelled' in 'TokenVariableMap[/]' with value 'false'
 2012-08-03 15:59:49,560  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_package' in 'TokenVariableMap[/]' with value 'Node Type: {http://www.alfresco.org/model/bpm/1.0}package, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/system/1.0}localized, {http://www.alfresco.org/model/bpm/1.0}workflowPackage]'
 2012-08-03 15:59:49,562  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'companyhome' in 'TokenVariableMap[/]' with value 'Node Type: {http://www.alfresco.org/model/content/1.0}folder, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/application/1.0}uifacets, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/content/1.0}titled, {http://www.alfresco.org/model/system/1.0}localized]'
 2012-08-03 15:59:49,564  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'initiator' in 'TokenVariableMap[/]' with value 'Node Type: {http://www.alfresco.org/model/content/1.0}person, Node Aspects: [{http://www.alfresco.org/model/application/1.0}configurable, {http://www.alfresco.org/model/content/1.0}ownable, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/system/1.0}localized, {http://www.alfresco.org/model/content/1.0}preferences]'
 2012-08-03 15:59:49,564  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'initiatorhome' in 'TokenVariableMap[/]' with value 'Node Type: {http://www.alfresco.org/model/content/1.0}folder, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/application/1.0}uifacets, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/content/1.0}titled, {http://www.alfresco.org/model/system/1.0}localized]'
 2012-08-03 15:59:49,566  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'workflowinstanceid' in 'TokenVariableMap[/]' with value 'jbpm$5239'
 2012-08-03 15:59:49,566  DEBUG [graph.def.GraphElement] [http-8081-6] event 'task-create' on 'Task(docusignwf:workflow_init)' for 'Token(/)'
 2012-08-03 15:59:49,568  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_percentComplete' in 'TaskInstance(docusignwf:workflow_init)' with value '0'
 2012-08-03 15:59:49,570  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_status' in 'TaskInstance(docusignwf:workflow_init)' with value 'Not Yet Started'
 2012-08-03 15:59:49,570  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_sendEMailNotifications' in 'TaskInstance(docusignwf:workflow_init)' with value 'false'
 2012-08-03 15:59:49,570  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_reassignable' in 'TaskInstance(docusignwf:workflow_init)' with value 'true'
 2012-08-03 15:59:49,570  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_hiddenTransitions' in 'TaskInstance(docusignwf:workflow_init)' with value ''
 2012-08-03 15:59:49,570  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_workflowPriority' in 'TaskInstance(docusignwf:workflow_init)' with value '2'
 2012-08-03 15:59:49,570  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_packageActionGroup' in 'TaskInstance(docusignwf:workflow_init)' with value 'add_package_item_actions'
 2012-08-03 15:59:49,570  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_packageItemActionGroup' in 'TaskInstance(docusignwf:workflow_init)' with value 'start_package_item_actions'
 2012-08-03 15:59:49,572  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] assigning task 'docusignwf:workflow_init' to 'admin'
 2012-08-03 15:59:49,572  DEBUG [graph.def.GraphElement] [http-8081-6] event 'task-assign' on 'Task(docusignwf:workflow_init)' for 'Token(/)'
 2012-08-03 15:59:49,572  DEBUG [context.exe.VariableContainer] [http-8081-6] update variable 'bpm_percentComplete' in 'TaskInstance(docusignwf:workflow_init)' to value '0'
 2012-08-03 15:59:49,572  DEBUG [context.exe.VariableContainer] [http-8081-6] update variable 'bpm_status' in 'TaskInstance(docusignwf:workflow_init)' to value 'Not Yet Started'
 2012-08-03 15:59:49,572  DEBUG [context.exe.VariableContainer] [http-8081-6] update variable 'bpm_sendEMailNotifications' in 'TaskInstance(docusignwf:workflow_init)' to value 'false'
 2012-08-03 15:59:49,574  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_package' in 'TaskInstance(docusignwf:workflow_init)' with value 'Node Type: {http://www.alfresco.org/model/bpm/1.0}package, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/system/1.0}localized, {http://www.alfresco.org/model/bpm/1.0}workflowPackage]'
 2012-08-03 15:59:49,574  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_workflowDescription' in 'TaskInstance(docusignwf:workflow_init)' with value ''
 2012-08-03 15:59:49,574  DEBUG [context.exe.VariableContainer] [http-8081-6] update variable 'bpm_workflowPriority' in 'TaskInstance(docusignwf:workflow_init)' to value '2'
 2012-08-03 15:59:49,574  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'docusignwf_request_signature_from' in 'TaskInstance(docusignwf:workflow_init)' with value '(snip)'
 2012-08-03 15:59:49,574  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_workflowDueDate' in 'TaskInstance(docusignwf:workflow_init)' with value 'null'
 2012-08-03 15:59:49,574  DEBUG [jbpm.svc.Services] [http-8081-6] executing default save operations
 2012-08-03 15:59:49,574  DEBUG [svc.save.HibernateSaveOperation] [http-8081-6] saving process instance
 2012-08-03 15:59:49,574  DEBUG [svc.save.SaveLogsOperation] [http-8081-6] flushing logs to logging service.
 2012-08-03 15:59:49,597  DEBUG [svc.save.CascadeSaveOperation] [http-8081-6] cascading save of 'ProcessInstance(9a17c9cc-b4f1-47d5-b8a3-bdfdfb4aa0a0)'
 2012-08-03 15:59:49,609  DEBUG [persistence.db.DbPersistenceService] [http-8081-6] injecting a session disables transaction
 2012-08-03 15:59:49,697  DEBUG [persistence.db.DbPersistenceService] [http-8081-6] injecting a session disables transaction
 2012-08-03 15:59:49,697  DEBUG [context.exe.VariableContainer] [http-8081-6] update variable 'bpm_status' in 'TaskInstance(docusignwf:workflow_init)' to value 'Completed'
 2012-08-03 15:59:49,697  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_outcome' in 'TaskInstance(docusignwf:workflow_init)' with value 'setup'
 2012-08-03 15:59:49,697  DEBUG [graph.def.GraphElement] [http-8081-6] event 'task-end' on 'Task(docusignwf:workflow_init)' for 'Token(/)'
 2012-08-03 15:59:49,697  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'bpm_percentComplete' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,697  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_percentComplete' in 'TokenVariableMap[/]' with value '0'
 2012-08-03 15:59:49,699  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'bpm_sendEMailNotifications' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,699  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_sendEMailNotifications' in 'TokenVariableMap[/]' with value 'false'
 2012-08-03 15:59:49,699  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'bpm_hiddenTransitions' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,699  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_hiddenTransitions' in 'TokenVariableMap[/]' with value ''
 2012-08-03 15:59:49,699  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'bpm_package' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,699  DEBUG [context.exe.VariableContainer] [http-8081-6] update variable 'bpm_package' in 'TokenVariableMap[/]' to value 'Node Type: {http://www.alfresco.org/model/bpm/1.0}package, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/system/1.0}localized, {http://www.alfresco.org/model/bpm/1.0}workflowPackage]'
 2012-08-03 15:59:49,699  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'bpm_reassignable' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,699  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_reassignable' in 'TokenVariableMap[/]' with value 'true'
 2012-08-03 15:59:49,699  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'bpm_workflowDescription' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,699  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_workflowDescription' in 'TokenVariableMap[/]' with value ''
 2012-08-03 15:59:49,699  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'bpm_workflowDueDate' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,699  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_workflowDueDate' in 'TokenVariableMap[/]' with value 'null'
 2012-08-03 15:59:49,699  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'bpm_status' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,699  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_status' in 'TokenVariableMap[/]' with value 'Completed'
 2012-08-03 15:59:49,699  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'bpm_packageActionGroup' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,699  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_packageActionGroup' in 'TokenVariableMap[/]' with value 'add_package_item_actions'
 2012-08-03 15:59:49,699  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'bpm_packageItemActionGroup' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,699  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_packageItemActionGroup' in 'TokenVariableMap[/]' with value 'start_package_item_actions'
 2012-08-03 15:59:49,699  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'bpm_workflowPriority' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,699  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_workflowPriority' in 'TokenVariableMap[/]' with value '2'
 2012-08-03 15:59:49,699  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'bpm_outcome' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,701  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'bpm_outcome' in 'TokenVariableMap[/]' with value 'setup'
 2012-08-03 15:59:49,701  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] flushing variable 'docusignwf_request_signature_from' from task 'docusignwf:workflow_init' to process variables
 2012-08-03 15:59:49,701  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'docusignwf_request_signature_from' in 'TokenVariableMap[/]' with value '(snip)'
 2012-08-03 15:59:49,701  DEBUG [taskmgmt.exe.TaskInstance] [http-8081-6] completion of task 'docusignwf:workflow_init' results in taking the default transition
 2012-08-03 15:59:49,701  DEBUG [graph.def.GraphElement] [http-8081-6] event 'before-signal' on 'StartState(start)' for 'Token(/)'
 2012-08-03 15:59:49,701  DEBUG [graph.def.GraphElement] [http-8081-6] event 'node-leave' on 'StartState(start)' for 'Token(/)'
 2012-08-03 15:59:49,701  DEBUG [graph.def.GraphElement] [http-8081-6] event 'transition' on 'Transition(setup)' for 'Token(/)'
 2012-08-03 15:59:49,705  DEBUG [graph.def.GraphElement] [http-8081-6] executing action 'Script(6b191295)'
 2012-08-03 15:59:49,705  DEBUG [graph.exe.Token] [http-8081-6] token[5240] is locked by token[5240]
 2012-08-03 15:59:49,711  DEBUG [graph.action.Script] [http-8081-6] script input: {bpm_percentComplete=0, bpm_sendEMailNotifications=false, task=null, bpm_hiddenTransitions=, bpm_package=Node Type: {http://www.alfresco.org/model/bpm/1.0}package, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/system/1.0}localized, {http://www.alfresco.org/model/bpm/1.0}workflowPackage], cancelled=false, workflowinstanceid=jbpm$5239, initiatorhome=Node Type: {http://www.alfresco.org/model/content/1.0}folder, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/application/1.0}uifacets, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/content/1.0}titled, {http://www.alfresco.org/model/system/1.0}localized], bpm_reassignable=true, bpm_workflowDueDate=null, bpm_workflowDescription=, node=null, bpm_status=Completed, companyhome=Node Type: {http://www.alfresco.org/model/content/1.0}folder, Node Aspects: [{http://www.alfresco.org/model/content/1.0}auditable, {http://www.alfresco.org/model/application/1.0}uifacets, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/content/1.0}titled, {http://www.alfresco.org/model/system/1.0}localized], bpm_packageActionGroup=add_package_item_actions, initiator=Node Type: {http://www.alfresco.org/model/content/1.0}person, Node Aspects: [{http://www.alfresco.org/model/application/1.0}configurable, {http://www.alfresco.org/model/content/1.0}ownable, {http://www.alfresco.org/model/system/1.0}referenceable, {http://www.alfresco.org/model/system/1.0}localized, {http://www.alfresco.org/model/content/1.0}preferences], token=Token(/), bpm_packageItemActionGroup=start_package_item_actions, bpm_outcome=setup, bpm_workflowPriority=2, executionContext=ExecutionContext[Token(/)], docusignwf_request_signature_from=(snip), taskInstance=null}
 2012-08-03 15:59:49,888  DEBUG [graph.action.Script] [http-8081-6] script output: {has_folders=no, waiting_folder=null, integrator_key=(snip), signer_email=(snip), signed_folder=null, uuid=6822a43c-3b59-40a4-b074-5761a257d2f9}
 2012-08-03 15:59:49,888  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'has_folders' in 'TokenVariableMap[/]' with value 'no'
 2012-08-03 15:59:49,888  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'waiting_folder' in 'TokenVariableMap[/]' with value 'null'
 2012-08-03 15:59:49,888  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'integrator_key' in 'TokenVariableMap[/]' with value '(snip)'
 2012-08-03 15:59:49,888  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'signer_email' in 'TokenVariableMap[/]' with value '(snip)'
 2012-08-03 15:59:49,888  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'signed_folder' in 'TokenVariableMap[/]' with value 'null'
 2012-08-03 15:59:49,888  DEBUG [context.exe.VariableContainer] [http-8081-6] create variable 'uuid' in 'TokenVariableMap[/]' with value '6822a43c-3b59-40a4-b074-5761a257d2f9'
 2012-08-03 15:59:49,892  DEBUG [jbpm.bytes.ByteBlockChopper] [http-8081-6] no need to chop 80 bytes
 2012-08-03 15:59:49,892  DEBUG [graph.exe.Token] [http-8081-6] token[5240] is unlocked by token[5240]
 2012-08-03 15:59:49,894  DEBUG [graph.def.GraphElement] [http-8081-6] event 'node-enter' on 'Decision(check_folders)' for 'Token(/)'
 2012-08-03 15:59:49,902  DEBUG [graph.def.GraphElement] [http-8081-6] executing action 'Action(ece5b80)'
 2012-08-03 15:59:49,902  DEBUG [graph.exe.Token] [http-8081-6] token[5240] is locked by token[5240]
 Workflow did NOT provide folders.
   And a document didn't, either (wasn't signable). So we need some folders.
2012-08-03 15:59:49,988  DEBUG [context.exe.VariableContainer] [http-8081-6] update variable 'has_folders' in 'TokenVariableMap[/]' to value 'no'
 2012-08-03 15:59:49,988  DEBUG [graph.exe.Token] [http-8081-6] token[5240] is unlocked by token[5240]
 2012-08-03 15:59:50,049  DEBUG [graph.node.Decision] [http-8081-6] decision didn't select transition, taking default Transition(no_folders)
 2012-08-03 15:59:50,049  DEBUG [graph.node.Decision] [http-8081-6] decision check_folders is taking 'Transition(no_folders)'
 2012-08-03 15:59:50,049  DEBUG [graph.def.GraphElement] [http-8081-6] event 'node-leave' on 'Decision(check_folders)' for 'Token(/)'
 2012-08-03 15:59:50,049  DEBUG [graph.def.GraphElement] [http-8081-6] event 'transition' on 'Transition(no_folders)' for 'Token(/)'
 2012-08-03 15:59:50,053  DEBUG [graph.def.GraphElement] [http-8081-6] event 'node-enter' on 'TaskNode(need_folders)' for 'Token(/)'
 2012-08-03 15:59:50,058  DEBUG [graph.def.GraphElement] [http-8081-6] event 'task-create' on 'Task(docusignwf:requesting_folders)' for 'Token(/)'
 2012-08-03 15:59:50,140  DEBUG [org.jbpm.JbpmContext] [http-8081-6] closing jbpmContext org.jbpm.JbpmContext@53ec452c
 2012-08-03 15:59:50,142  DEBUG [jbpm.svc.Services] [http-8081-6] closing service 'persistence': org.jbpm.persistence.db.DbPersistenceService@b49ca9
 2012-08-03 15:59:50,142  DEBUG [jbpm.svc.Services] [http-8081-6] closing service 'tx': org.jbpm.tx.TxService@51991b9b
 2012-08-03 15:59:50,142  DEBUG [jbpm.svc.Services] [http-8081-6] closing service 'logging': org.jbpm.logging.db.DbLoggingService@1ae386f7
 2012-08-03 15:59:50,142  DEBUG [jbpm.svc.Services] [http-8081-6] closing service 'authentication': org.jbpm.security.authentication.DefaultAuthenticationService@4fb1cfeb
 2012-08-03 15:59:50,142  DEBUG [alfresco.repo.workflow] [http-8081-6] Detached (rollback) JBPM Context from transaction 5bc0a306-603c-44f9-ae65-5641cacd2eab‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

I have a four primary questions:

(obviously) How do I get the FAILING WORKFLOW to start working?
How can I get more useful information about what actually happens at the point of failure?
Where should I start looking for the cause of this?
What other information would help people answer my first question?

Find more posts tagged with

Comments

afaust

Hello,

not being able to find the necessary cause of an error is a common problem with workflows in Alfresco. For some reason, most of the information is dropped at the interface between Alfresco and the workflow engine without being logged ("some reason" = lack of consideration from a developer?).
From experience, your best option at this point is to activate the remote Java debugger of your choice and put a breakpoint in JBPMEngine.getStartWorkflowException() - then you will have access to the underlying exception. If your debugger supports executing expressions, you should try a "e.printStackTrace()" to have the information printed into the console / logs. That information may (!) then be sufficient to identify the cause or point you into a more detailed direction of investigation.

Regards
Axel