search

yawlfoundation / yawl

Yet Another Workflow Language
http://www.yawlfoundation.org
GNU Lesser General Public License v3.0
88 stars 35 forks source link

Work item goes missing after Enabled announcement (No work item found with id) #611

Closed mlawry closed 7 years ago

mlawry commented 7 years ago

Hi, I have a specification like this:

Root Net

Subnet

The begin and end tasks are automated, so when a new case is started from this specification, there should be 3 tasks: 0, 1 and 2; all belonging to the subnet. I have included the full XML specification at the end.

The issue I'm having is that sometimes, after a new case is started from the specification, one or more of the work items representing tasks 0, 1 or 2 will go missing. For example,

  1. A new case is started from the specification.
  2. My custom (InterfaceB) service gets notified that these three work items are enabled.
  3. My custom service attempts to checkout the three work items, one after another.
  4. Exception returned by YAWL saying one of the work items does not exist.

I've done some debugging. I’ve added extra log messages to the YWorkItemRepository class. When I run YAWL engine with this modified class (I replaced the yawl-lib-4.1.jar file) and start a new case, here is the yawl_engine.log output:

Legend:
- Case ID: 63
- Task ID for begin: a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin
- Task ID for 0: a9790c0bd-47e3-4826-92bd-e5064f8b08c9_75b0d64c-2717-41b6-958c-1cc1dc823917
- Task ID for 1: a9790c0bd-47e3-4826-92bd-e5064f8b08c9_85b0d64c-2717-41b6-958c-1cc1dc823917
- Task ID for 2: a9790c0bd-47e3-4826-92bd-e5064f8b08c9_95b0d64c-2717-41b6-958c-1cc1dc823917
                                                       ^
                                                    This digit is different

2017-08-31 05:49:24,627 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:24,627 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:24,646 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:24,647 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:28,038 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#add: 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin
2017-08-31 05:49:28,235 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#get: 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin
2017-08-31 05:49:28,334 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#add: 63.1.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin
2017-08-31 05:49:28,596 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#get: 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin
2017-08-31 05:49:28,596 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getChildrenOf: 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin
2017-08-31 05:49:28,596 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getChildrenOf: children = [YWorkItem : 63.1.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin]
2017-08-31 05:49:28,667 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#get: 63.1.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin
2017-08-31 05:49:28,832 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:28,836 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:28,856 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:28,856 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:28,876 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:28,877 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:28,887 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:28,887 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:28,904 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:28,904 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:29,004 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:29,005 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:29,023 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:29,023 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:29,039 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:29,040 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:29,071 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:29,071 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:29,084 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:29,085 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:29,105 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:29,106 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:29,130 [WARN ] YWorkItemRepository  :- --> removeWorkItemFamily: <workItem instructions="&#xD;{[contacts]}&#xD;&#xD;{[contacts_information]}&#xD;&#xD;{[contacts_filenotes]}&#xD;" ndheight="120" ndleft="-1161" ndtop="25" ndwidth="120" expectedEffortSeconds=""><taskid>a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin</taskid><caseid>63.1.1</caseid><uniqueid>000000000000000000000004C</uniqueid><taskname>begin</taskname><documentation></documentation><specidentifier>UID_b3c3bde7-17e5-4c99-8281-60b793aed0d6</specidentifier><specversion>1.0</specversion><specuri>Checklist_Task</specuri><status>Complete</status><allowsdynamiccreation>false</allowsdynamiccreation><requiresmanualresourcing>false</requiresmanualresourcing><codelet/><data><a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin instructions="&#xD;{[contacts]}&#xD;&#xD;{[contacts_information]}&#xD;&#xD;{[contacts_filenotes]}&#xD;" ndheight="120" ndleft="-1161" ndtop="25" ndwidth="120" expectedEffortSeconds="" /></data><enablementTime>Aug:31, 2017 5:49:28</enablementTime><enablementTimeMs>1504158568039</enablementTimeMs><firingTime>Aug:31, 2017 5:49:28</firingTime><firingTimeMs>1504158568336</firingTimeMs><startTime>Aug:31, 2017 5:49:28</startTime><startTimeMs>1504158568482</startTimeMs><startedBy>DefaultWorklist</startedBy></workItem>
2017-08-31 05:49:29,134 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#remove: 63.1.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin
2017-08-31 05:49:29,134 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#remove: 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin
2017-08-31 05:49:29,134 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#add: 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_85b0d64c-2717-41b6-958c-1cc1dc823917
2017-08-31 05:49:29,194 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:29,194 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#cleanseRepository: will remove 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_85b0d64c-2717-41b6-958c-1cc1dc823917
2017-08-31 05:49:29,194 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: [63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_85b0d64c-2717-41b6-958c-1cc1dc823917]
2017-08-31 05:49:29,209 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:29,223 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:29,238 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:29,238 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:29,284 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:29,284 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:29,298 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:29,298 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:29,308 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#getWorkItems
2017-08-31 05:49:29,308 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#removeItems: []
2017-08-31 05:49:29,338 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#add: 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_95b0d64c-2717-41b6-958c-1cc1dc823917
2017-08-31 05:49:29,448 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#add: 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_75b0d64c-2717-41b6-958c-1cc1dc823917
2017-08-31 05:49:40,839 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#get: 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_75b0d64c-2717-41b6-958c-1cc1dc823917
2017-08-31 05:49:40,935 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#add: 63.1.2:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_75b0d64c-2717-41b6-958c-1cc1dc823917
2017-08-31 05:49:41,258 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#get: 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_95b0d64c-2717-41b6-958c-1cc1dc823917
2017-08-31 05:49:41,382 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#add: 63.1.3:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_95b0d64c-2717-41b6-958c-1cc1dc823917
2017-08-31 05:49:41,661 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#get: 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_85b0d64c-2717-41b6-958c-1cc1dc823917
2017-08-31 05:49:41,681 [WARN ] YWorkItemRepository  :-
*** DUMPING 63 ENTRIES IN ID_2_WORKITEMS_MAP ***
......
2017-08-31 05:49:41,707 [WARN ] YWorkItemRepository  :- *** DUMP OF CASE_2_NETRUNNER_MAP ENDS

As you can see, it looks like work item 1 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_85b0d64c-2717-41b6-958c-1cc1dc823917 was added immediately after work item 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin is removed. However, the following cleanseRepository() call removes this work item, which ends up as missing. The other two work items 0 and 2 are added later on. When we try to retrieve work item 1 again, it is missing so the dump code is triggered. (I added the dump as a marker to indicate a work item is missing.)

The actual exception raised by YAWL is:

org.yawlfoundation.yawl.exceptions.YAWLException: <failure><reason>No work item found with id = 63.1:a9790c0bd-47e3-4826-92bd-e5064f8b08c9_85b0d64c-2717-41b6-958c-1cc1dc823917</reason></failure>
  at org.yawlfoundation.yawl.engine.interfce.interfaceB.InterfaceBWebsideController.checkOut(InterfaceBWebsideController.java:320) ~[yawl-lib-4.1.jar:?]

I hope you can find out why work item 1 gets removed, because I have no idea. But if you need more debug info, please let me know. Finally, the full specification is below:

<?xml version="1.0" encoding="UTF-8"?>
<specificationSet xmlns="http://www.yawlfoundation.org/yawlschema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" version="3.0" xsi:schemaLocation="http://www.yawlfoundation.org/yawlschema http://www.yawlfoundation.org/yawlschema/YAWL_Schema3.0.xsd">
  <specification uri="Checklist_Task">
    <name>Checklist Task</name>
    <documentation>Test checklist subnets.</documentation>
    <metaData>
      <title>Checklist Task</title>
      <creator>Lawrence Yao</creator>
      <description>Test checklist subnets.</description>
      <version>1.0</version>
      <persistent>false</persistent>
      <identifier>UID_3f4327e1-f74f-43e5-a445-4933db7a4711</identifier>
    </metaData>
    <decomposition id="Net" isRootNet="true" xsi:type="NetFactsType">
      <processControlElements>
        <inputCondition id="input">
          <flowsInto>
            <nextElementRef id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9" />
          </flowsInto>
        </inputCondition>
        <task id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9">
          <name>Task with a checklist</name>
          <documentation>Task with a checklist.</documentation>
          <flowsInto>
            <nextElementRef id="d7a79471-0a1d-4899-a7c7-72cf3ba312ea" />
          </flowsInto>
          <join code="and" />
          <split code="and" />
          <decomposesTo id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9" />
        </task>
        <task id="d7a79471-0a1d-4899-a7c7-72cf3ba312ea">
          <name>Skip over this task</name>
          <documentation>Skip over this task because the effort is zero.</documentation>
          <flowsInto>
            <nextElementRef id="output" />
          </flowsInto>
          <join code="and" />
          <split code="and" />
          <resourcing>
            <offer initiator="system">
              <distributionSet>
                <initialSet />
              </distributionSet>
            </offer>
            <allocate initiator="user" />
            <start initiator="user" />
          </resourcing>
          <decomposesTo id="d7a79471-0a1d-4899-a7c7-72cf3ba312ea" />
        </task>
        <outputCondition id="output" />
      </processControlElements>
    </decomposition>
    <decomposition id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9" xsi:type="NetFactsType">
      <outputParam>
        <index>0</index>
        <name>checklist_a9790c0bd-47e3-4826-92bd-e5064f8b08c9</name>
        <type>string</type>
        <namespace>http://www.w3.org/2001/XMLSchema</namespace>
      </outputParam>
      <localVariable>
        <index>0</index>
        <name>checklist_a9790c0bd-47e3-4826-92bd-e5064f8b08c9</name>
        <type>string</type>
        <namespace>http://www.w3.org/2001/XMLSchema</namespace>
      </localVariable>
      <localVariable>
        <index>1</index>
        <name>checklist_item_0</name>
        <type>string</type>
        <namespace>http://www.w3.org/2001/XMLSchema</namespace>
      </localVariable>
      <localVariable>
        <index>2</index>
        <name>checklist_item_1</name>
        <type>string</type>
        <namespace>http://www.w3.org/2001/XMLSchema</namespace>
      </localVariable>
      <localVariable>
        <index>3</index>
        <name>checklist_item_2</name>
        <type>string</type>
        <namespace>http://www.w3.org/2001/XMLSchema</namespace>
      </localVariable>
      <processControlElements>
        <inputCondition id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_input">
          <flowsInto>
            <nextElementRef id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin" />
          </flowsInto>
        </inputCondition>
        <task id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin">
          <name>begin</name>
          <documentation />
          <flowsInto>
            <nextElementRef id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_95b0d64c-2717-41b6-958c-1cc1dc823917" />
          </flowsInto>
          <flowsInto>
            <nextElementRef id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_75b0d64c-2717-41b6-958c-1cc1dc823917" />
          </flowsInto>
          <flowsInto>
            <nextElementRef id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_85b0d64c-2717-41b6-958c-1cc1dc823917" />
          </flowsInto>
          <join code="and" />
          <split code="and" />
          <resourcing>
            <offer initiator="user" />
            <allocate initiator="user" />
            <start initiator="user" />
          </resourcing>
          <decomposesTo id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin" />
        </task>
        <task id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_75b0d64c-2717-41b6-958c-1cc1dc823917">
          <name>0</name>
          <documentation>Completing this item is optional.</documentation>
          <flowsInto>
            <nextElementRef id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_end" />
          </flowsInto>
          <join code="and" />
          <split code="and" />
          <completedMappings>
            <mapping>
              <expression query="&lt;checklist_item_0&gt;{/a9790c0bd-47e3-4826-92bd-e5064f8b08c9_75b0d64c-2717-41b6-958c-1cc1dc823917/checklist_item_0/text()}&lt;/checklist_item_0&gt;" />
              <mapsTo>checklist_item_0</mapsTo>
            </mapping>
          </completedMappings>
          <resourcing>
            <offer initiator="user" />
            <allocate initiator="user" />
            <start initiator="user" />
          </resourcing>
          <decomposesTo id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_75b0d64c-2717-41b6-958c-1cc1dc823917" />
        </task>
        <task id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_85b0d64c-2717-41b6-958c-1cc1dc823917">
          <name>1</name>
          <documentation>You must complete this item.</documentation>
          <flowsInto>
            <nextElementRef id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_end" />
          </flowsInto>
          <join code="and" />
          <split code="and" />
          <completedMappings>
            <mapping>
              <expression query="&lt;checklist_item_1&gt;{/a9790c0bd-47e3-4826-92bd-e5064f8b08c9_85b0d64c-2717-41b6-958c-1cc1dc823917/checklist_item_1/text()}&lt;/checklist_item_1&gt;" />
              <mapsTo>checklist_item_1</mapsTo>
            </mapping>
          </completedMappings>
          <resourcing>
            <offer initiator="user" />
            <allocate initiator="user" />
            <start initiator="user" />
          </resourcing>
          <decomposesTo id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_85b0d64c-2717-41b6-958c-1cc1dc823917" />
        </task>
        <task id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_95b0d64c-2717-41b6-958c-1cc1dc823917">
          <name>2</name>
          <documentation>A mandatory checklist item.</documentation>
          <flowsInto>
            <nextElementRef id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_end" />
          </flowsInto>
          <join code="and" />
          <split code="and" />
          <completedMappings>
            <mapping>
              <expression query="&lt;checklist_item_2&gt;{/a9790c0bd-47e3-4826-92bd-e5064f8b08c9_95b0d64c-2717-41b6-958c-1cc1dc823917/checklist_item_2/text()}&lt;/checklist_item_2&gt;" />
              <mapsTo>checklist_item_2</mapsTo>
            </mapping>
          </completedMappings>
          <resourcing>
            <offer initiator="user" />
            <allocate initiator="user" />
            <start initiator="user" />
          </resourcing>
          <decomposesTo id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_95b0d64c-2717-41b6-958c-1cc1dc823917" />
        </task>
        <task id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_end">
          <name>end</name>
          <documentation />
          <flowsInto>
            <nextElementRef id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_output" />
          </flowsInto>
          <join code="and" />
          <split code="and" />
          <startingMappings>
            <mapping>
              <expression query="&lt;checklist_a9790c0bd-47e3-4826-92bd-e5064f8b08c9&gt;{ concat( /a9790c0bd-47e3-4826-92bd-e5064f8b08c9/checklist_item_0/text() , ':' , /a9790c0bd-47e3-4826-92bd-e5064f8b08c9/checklist_item_1/text() , ':' , /a9790c0bd-47e3-4826-92bd-e5064f8b08c9/checklist_item_2/text() ) }&lt;/checklist_a9790c0bd-47e3-4826-92bd-e5064f8b08c9&gt;" />
              <mapsTo>checklist_a9790c0bd-47e3-4826-92bd-e5064f8b08c9</mapsTo>
            </mapping>
          </startingMappings>
          <completedMappings>
            <mapping>
              <expression query="&lt;checklist_a9790c0bd-47e3-4826-92bd-e5064f8b08c9&gt;{/a9790c0bd-47e3-4826-92bd-e5064f8b08c9_end/checklist_a9790c0bd-47e3-4826-92bd-e5064f8b08c9/text()}&lt;/checklist_a9790c0bd-47e3-4826-92bd-e5064f8b08c9&gt;" />
              <mapsTo>checklist_a9790c0bd-47e3-4826-92bd-e5064f8b08c9</mapsTo>
            </mapping>
          </completedMappings>
          <resourcing>
            <offer initiator="user" />
            <allocate initiator="user" />
            <start initiator="user" />
          </resourcing>
          <decomposesTo id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_end" />
        </task>
        <outputCondition id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_output" />
      </processControlElements>
    </decomposition>
    <decomposition id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_75b0d64c-2717-41b6-958c-1cc1dc823917" xsi:type="WebServiceGatewayFactsType" checklistType="checkbox" checklistItemCount="3" checklistItemId="75b0d64c-2717-41b6-958c-1cc1dc823917" checklistOptional="True" checklistTaskId="a9790c0bd-47e3-4826-92bd-e5064f8b08c9">
      <name>Completing this item is optional.</name>
      <outputParam>
        <index>0</index>
        <name>checklist_item_0</name>
        <type>string</type>
        <namespace>http://www.w3.org/2001/XMLSchema</namespace>
      </outputParam>
      <yawlService id="http://yawlshim-service/ib" />
      <externalInteraction>manual</externalInteraction>
    </decomposition>
    <decomposition id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_85b0d64c-2717-41b6-958c-1cc1dc823917" xsi:type="WebServiceGatewayFactsType" checklistItemCount="3" checklistType="checkbox" checklistItemId="85b0d64c-2717-41b6-958c-1cc1dc823917" checklistOptional="False" checklistTaskId="a9790c0bd-47e3-4826-92bd-e5064f8b08c9">
      <name>You must complete this item.</name>
      <outputParam>
        <index>0</index>
        <name>checklist_item_1</name>
        <type>string</type>
        <namespace>http://www.w3.org/2001/XMLSchema</namespace>
      </outputParam>
      <yawlService id="http://yawlshim-service/ib" />
      <externalInteraction>manual</externalInteraction>
    </decomposition>
    <decomposition id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_95b0d64c-2717-41b6-958c-1cc1dc823917" xsi:type="WebServiceGatewayFactsType" checklistItemCount="3" checklistType="" checklistItemId="95b0d64c-2717-41b6-958c-1cc1dc823917" checklistOptional="" checklistTaskId="a9790c0bd-47e3-4826-92bd-e5064f8b08c9">
      <name>A mandatory checklist item.</name>
      <outputParam>
        <index>0</index>
        <name>checklist_item_2</name>
        <type>string</type>
        <namespace>http://www.w3.org/2001/XMLSchema</namespace>
      </outputParam>
      <yawlService id="http://yawlshim-service/ib" />
      <externalInteraction>manual</externalInteraction>
    </decomposition>
    <decomposition id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_begin" xsi:type="WebServiceGatewayFactsType" ndheight="120" instructions="&#xD;{[contacts]}&#xD;&#xD;{[contacts_information]}&#xD;&#xD;{[contacts_filenotes]}&#xD;" ndtop="25" ndleft="-1161" ndwidth="120" expectedEffortSeconds="">
      <name>begin</name>
      <externalInteraction>automated</externalInteraction>
    </decomposition>
    <decomposition id="a9790c0bd-47e3-4826-92bd-e5064f8b08c9_end" xsi:type="WebServiceGatewayFactsType">
      <name>end</name>
      <inputParam>
        <index>0</index>
        <name>checklist_a9790c0bd-47e3-4826-92bd-e5064f8b08c9</name>
        <type>string</type>
        <namespace>http://www.w3.org/2001/XMLSchema</namespace>
      </inputParam>
      <outputParam>
        <index>0</index>
        <name>checklist_a9790c0bd-47e3-4826-92bd-e5064f8b08c9</name>
        <type>string</type>
        <namespace>http://www.w3.org/2001/XMLSchema</namespace>
      </outputParam>
      <externalInteraction>automated</externalInteraction>
    </decomposition>
    <decomposition id="d7a79471-0a1d-4899-a7c7-72cf3ba312ea" xsi:type="WebServiceGatewayFactsType" ndheight="120" instructions="&#xD;{[contacts_tasks]}&#xD;&#xD;{[contacts_services]}&#xD;&#xD;{[contacts_apps]}&#xD;" ndtop="25" ndleft="-907" ndwidth="120" expectedEffortSeconds="0">
      <name>Skip over this task</name>
      <yawlService id="http://yawlshim-service/ib" />
      <externalInteraction>manual</externalInteraction>
    </decomposition>
  </specification>
</specificationSet>
yawlfoundation commented 7 years ago

I believe the issue is fixed in the latest commit - please test at your end, and close this issue if satisfied. It relates to a race condition between cleanseRepository and YNetRunner#fireAtomicTask; the latter announced the firing to services before it 'stores' the new work item, hence the item would not being found in cleanseRepository's call to YNetRunner if it came before the item is added to _enabledTasks.

In your debug output there are numerous frequent calls to getWorkItems, which don't occur in the normal course of events. Are they generated from your service?

mlawry commented 7 years ago

Thanks for the quick response. I've deployed your fix and things are looking good so far, I'll let it run for a few days and close this issue if all is fine.

The frequent calls to getWorkItems are calls from my custom service. The custom service handles multiple users and the implementation is quite chatty at the moment, so there ends up being lots of calls to get the list of work items (usually via getWorkItemsForCase()).

mlawry commented 7 years ago

The issue happened again today. Again, a work item was removed in the cleanseRepository method immediately after it was added. I've managed to get some more information. The yawl_engine.log entries are:

2017-09-05 06:18:39,546 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#add: 78.1:a45290ebc-8f46-44a4-8e6d-c280f4e9d164_end
2017-09-05 06:18:39,750 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#add: 78.1.4:a45290ebc-8f46-44a4-8e6d-c280f4e9d164_end
2017-09-05 06:18:40,572 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#add: 78.2:a4e3e5ea3-f0b6-4aaf-aa16-bbcf55921c40_begin
2017-09-05 06:18:40,580 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#cleanseRepository: will remove 78.2:a4e3e5ea3-f0b6-4aaf-aa16-bbc
f55921c40_begin
2017-09-05 06:18:40,589 [WARN ] YWorkItemRepository  :- --> YWorkItemRepository#cleanseRepository will remove
java.lang.RuntimeException: cleanseRepository.
    at org.yawlfoundation.yawl.engine.YWorkItemRepository.cleanseRepository(YWorkItemRepository.java:206) [yawl-lib-4.1.jar:?]
    at org.yawlfoundation.yawl.engine.YWorkItemRepository.getWorkItems(YWorkItemRepository.java:177) [yawl-lib-4.1.jar:?]
    at org.yawlfoundation.yawl.engine.YWorkItemRepository.getWorkItemsWithIdentifier(YWorkItemRepository.java:269) [yawl-lib-4.1.jar:?]
    at org.yawlfoundation.yawl.engine.interfce.EngineGatewayImpl.getWorkItemsWithIdentifier(EngineGatewayImpl.java:583) [yawl-lib-4.1.jar:?]
    at org.yawlfoundation.yawl.engine.interfce.interfaceB.InterfaceB_EngineBasedServer.processPostQuery(InterfaceB_EngineBasedServer.java:339) [yawl-lib-4.1.jar:?]
    at org.yawlfoundation.yawl.engine.interfce.interfaceB.InterfaceB_EngineBasedServer.doPost(InterfaceB_EngineBasedServer.java:224) [yawl-lib-4.1.jar:?]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:648) [tomcat8-servlet-api-8.0.32.jar:?]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:729) [tomcat8-servlet-api-8.0.32.jar:?]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292) [tomcat8-catalina-8.0.32.jar:8.0.32]

The YWorkItemRepository.cleanseRepository method is slightly different to before:

public void cleanseRepository() {
    Set<String> itemsToRemove = new HashSet<String>();
    for (YWorkItem workitem : _itemMap.values()) {
        YNetRunner runner = YEngine.getInstance().getNetRunnerRepository().get(workitem);

        if (runner != null) {                                      //MLF can be null
            boolean foundOne = false;
            for (YTask task : runner.getActiveTasks()) {
                if (task.getID().equals(workitem.getTaskID())) {
                    foundOne = true;
                    break;
                }
            }

            //clean up all the work items that are out of synch with the engine.
            if (! foundOne) {
                _logger.warn("--> YWorkItemRepository#cleanseRepository: will remove {}", workitem.getIDString()); 

                for (YTask task : runner.getActiveTasks()) {
                    _logger.warn("--> YWorkItemRepository#cleanseRepository: active task: {}", task.getID());
                }

                try {
                    throw new RuntimeException("cleanseRepository.");
                } catch (Exception ex) {
                    _logger.warn("--> YWorkItemRepository#cleanseRepository will remove", ex);
                }

                itemsToRemove.add(workitem.getIDString());
            }
        }
    }
    if (! itemsToRemove.isEmpty()) removeItems(itemsToRemove);
}

The above method logs the current active tasks when it finds a work item to remove, the log message would be "--> YWorkItemRepository#cleanseRepository: active task: {}". However, from the yawl_engine.log entries, there aren't any entries of this kind. So my conclusion is that runner.getActiveTasks() is returning an empty set.

Just to add, this problem only seems to occur for subnet work items, it never happened for any work items in the root net. In this case, the specification is different from the original post, but still has the same subnet structure (i.e. the uuid_begin and uuid_end task IDs is from a subnet with the exact same structure as the original post's subnet).

I'm thinking may be the runner variable is referring to the subnet, and because the first task in the subnet is an automated task, may be YAWL didn't get a chance to prepare the runner variable properly? Just a thought.

As indicated before, the cleanseRepository is actually triggered by my custom service.

yawlfoundation commented 7 years ago

I've made a further adjustment to YNetRunner#fireAtomicTask that ensures that the net runner has stored the enabled task as an active task before the first work item from the task is created. I think this will resolve the issue. Please check and close if satisfied.

mlawry commented 7 years ago

Thanks. I've deployed the latest and will close issue in a few days if it doesn't happen anymore.