Event Registry intermittent not correlating event

tjmac44 · August 2, 2021, 2:09pm

Using flowable version 6.6.0, I have a CMMN that listens to about 30 events using the event registry to listen to Rabbit. The case is started once a day. The events should complete a milestone within a given timer. About 50% of the time one or two events will not get correlated to the case instance.

We also have custom impl of MessageListener as there (this is to get the headers from the message into the event registry mappings for correlation):

@Slf4j
class EssChannelMessageListenerAdapter implements MessageListener {

    Collection<String> stringContentTypes
    EventRegistry eventRegistry
    InboundChannelModel inboundChannelModel
    ObjectMapper objectMapper

    EssChannelMessageListenerAdapter(
            EventRegistry eventRegistry,
            InboundChannelModel inboundChannelModel,
            ObjectMapper objectMapper
    ) {
        this.eventRegistry = eventRegistry
        this.inboundChannelModel = inboundChannelModel
        this.stringContentTypes = new HashSet<>()
        this.stringContentTypes.add(MessageProperties.CONTENT_TYPE_JSON)
        this.stringContentTypes.add(MessageProperties.CONTENT_TYPE_JSON_ALT)
        this.stringContentTypes.add(MessageProperties.CONTENT_TYPE_TEXT_PLAIN)
        this.stringContentTypes.add(MessageProperties.CONTENT_TYPE_XML)
        this.objectMapper = objectMapper
    }

    @Override
    void onMessage(Message message) {
        log.info("Received message: ${message}")
        byte[] body = message.getBody()
        MessageProperties messageProperties = message.getMessageProperties()
        String contentType = messageProperties != null ? messageProperties.getContentType() : null
        Map headers = messageProperties?.getHeaders()

        String rawEvent

        if (body == null) {
            rawEvent = null
        } else if (stringContentTypes.contains(contentType)) {
            rawEvent = convertInboundMessage(body, headers)
        } else {
            rawEvent = Base64.getEncoder().encodeToString(body)
        }
        log.info("Calling event receive with event: ${rawEvent}")
        eventRegistry.eventReceived(inboundChannelModel, rawEvent)
    }

    private String convertInboundMessage(byte[] body, Map headers) {
        Map payload = objectMapper.readValue(body, Map)
        objectMapper.writeValueAsString([headers: headers, payload: payload])
    }
}

The 2 log statements were also added to verify the correlation parameters, they log correctly but then eventRegistry.eventReceived(inboundChannelModel, rawEvent) is called and the expected updating of the event listeners does not happen. I can pull the message from the log files and send it by itself again and it will work.

Unfortunately I am hesitant to share the cmmn model do to it being proprietary to my business.

Any suggestions, i know this is vague, how to troubleshoot?

filiphr · August 11, 2021, 12:26pm

Hey @tjmac44,

In order to be able to understand the problem we would need to see how your channel and event definitions look like.

To me it looks like your event does not handle the newly created event properly. The event payload now has the structure of:

{
    headers: {},
    payload: {}
}

tjmac44 · August 19, 2021, 2:30pm

@filiphr

Sorry this response taking so long.

The event is handled properly about 40% of the time, meaning it receives the event and triggers the event listener. The other 60% it indeeds logs the statement mentioned above, but the event listener planned item does not get correlated and triggered.

Here is the event def (slightly modified to obscure):

{
  "key": "backfill-completed",
  "name": "Accounting Completed",
  "inboundChannelKeys": [
    "pricing-events"
  ],
  "correlationParameterType": {
    "business-scope": "string",
    "process-type": "string",
    "process-name": "string"
  },
  "correlationParameterMapping": {
    "business-scope": "/headers/business-scope",
    "process-type": "/headers/process-type",
    "process-name": "/headers/process-name"
  },
  "payload": [
    {
      "name": "payload",
      "type": "string"
    },
    {
      "name": "headers",
      "type": "string"
    }
  ]
}

channel def:

{
  "key": "pricing-events",
  "category": "channel",
  "name": "Pricing Events",
  "description": "Pricing Events",
  "channelType": "inbound",
  "type": "rabbit",
  "deserializerType": "json",
  "ackMode": "NONE",
  "payloadExtractorDelegateExpression": "${essInboundPayloadExtractor}",
  "channelEventKeyDetection": {
    "jsonPointerExpression": "/headers/type"
  },
  "queues": [
    "workflow-pricing-listeners"
  ],
  "exchange": "pricing-events"
}

Thanks for taking the time to help on this.

filiphr · August 23, 2021, 2:51pm

Hey @tjmac44,

Is it possible that you have events that do not have the structure

{
    headers: {},
    payload: {}
}

If that is the case then this would explain the problem.

You could try enabling debug level logging so you can see what is happening and why the event subscriptions are not found.

If you do not want to publicly share the model, there are ways through which you could get Flowable Support.
Without a model or logs we can’t help much.

Cheers,
Filip

tjmac44 · August 23, 2021, 3:05pm

@filiphr

What logger would you suggest setting to debug?

Here are some logging of the messages:

Worked as planned:

2021-08-16T23:37:14-05:00 4d42f4837f4f Calling event receive with event: {
“headers” : {
“process-name” : “confirm”,
“business-scope” : “trading”,
“process-type” : “confirm”,
“type” : “backfill-completed”
},
“payload” : {
“completedDateTime” : “2021-08-16T23:37:14.21862”
}

The next day the message did not trigger event and a timer terminated the case a few hours later. The planned items were marked as so in the DB.

2021-08-17T23:22:09-05:00 ee0b12f00a79 Calling event receive with event: {
“headers” : {
“process-name” : “confirm”,
“business-scope” : “trading”,
“process-type” : “confirm”,
“type” : “backfill-completed”
},
“payload” : {
“completedDateTime” : “2021-08-17T23:22:09.163966”
}

filiphr · August 23, 2021, 3:09pm

I would suggest putting org.flowable to debug. You would be able to see the inserts, queries, by flowable.

Cheers,
Filip

tjmac44 · September 3, 2021, 12:05pm

Sep 1, 202123:12:21.876
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.821 INFO [x] 8 — [rading-events-1] g.w.e.r.EssChannelMessageListenerAdapter : Calling event receive with event: {
“headers” : {
“dtdTraceTagInfo” : “FW4;-1371842560;1;-2138587146;7985;0;1835787862;749;633d;2h02;3h21f72453;4he3a8;5h01”,
“file-processed-correlation-id” : “5a0bf025-c6f0-8595-9d85-24891ffd50fd”,
“process-name” : “plan-trade-confirm”,
“business-scope” : “pricing-and-trading”,
“type” : “urn:com:mutualofomaha:gpa:reconciliation:processed-count-completed”,
“app-name” : “gpa-plan-trade-record-backfill-handler”
},
“payload” : {
“status” : “SUCCEEDED”,
“date” : “2021-09-01”,
“processedCount” : 5284
}

2021-09-01T23:12:21-05:00 44491 - - }

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.821 DEBUG [x] 8 — [rading-events-1] o.f.c.e.impl.interceptor.LogInterceptor : — starting GetEventModelCmd --------------------------------------------------------

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.821 DEBUG [x] 8 — [rading-events-1] o.f.c.s.SpringTransactionInterceptor : Running command with propagation REQUIRED

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.824 DEBUG [x] 8 — [rading-events-1] i.p.e.E.selectLatestEventDefinitionByKey : ==> Preparing: select * from FLW_EVENT_DEFINITION where KEY_ = ? and (TENANT_ID_ = ‘’ or TENANT_ID_ is null) and VERSION_ = (select max(VERSION_) from FLW_EVENT_DEFINITION where KEY_ = ? and (TENANT_ID_ = ‘’ or TENANT_ID_ is null))

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.824 DEBUG [x] 8 — [rading-events-1] i.p.e.E.selectLatestEventDefinitionByKey : ==> Parameters: urn:com:mutualofomaha:gpa:reconciliation:processed-count-completed(String), urn:com:mutualofomaha:gpa:reconciliation:processed-count-completed(String)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.825 DEBUG [x] 8 — [rading-events-1] i.p.e.E.selectLatestEventDefinitionByKey : <== Total: 1

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.826 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : Flushing dbSqlSession

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.826 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : flush summary: 0 insert, 0 update, 0 delete.

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.826 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : now executing flush…

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.827 DEBUG [x] 8 — [rading-events-1] o.f.c.e.impl.interceptor.LogInterceptor : — GetEventModelCmd finished --------------------------------------------------------

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.827 DEBUG [x] 8 — [rading-events-1] o.f.c.e.impl.interceptor.LogInterceptor : — starting GetChannelModelCmd --------------------------------------------------------

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.827 DEBUG [x] 8 — [rading-events-1] o.f.c.s.SpringTransactionInterceptor : Running command with propagation REQUIRED

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.828 DEBUG [x] 8 — [rading-events-1] p.e.C.selectLatestChannelDefinitionByKey : ==> Preparing: select * from FLW_CHANNEL_DEFINITION where KEY_ = ? and (TENANT_ID_ = ‘’ or TENANT_ID_ is null) and VERSION_ = (select max(VERSION_) from FLW_CHANNEL_DEFINITION where KEY_ = ? and (TENANT_ID_ = ‘’ or TENANT_ID_ is null))

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.828 DEBUG [x] 8 — [rading-events-1] p.e.C.selectLatestChannelDefinitionByKey : ==> Parameters: pricing-and-trading-events(String), pricing-and-trading-events(String)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.829 DEBUG [x] 8 — [rading-events-1] p.e.C.selectLatestChannelDefinitionByKey : <== Total: 1

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.829 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : Flushing dbSqlSession

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.829 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : flush summary: 0 insert, 0 update, 0 delete.

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.829 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : now executing flush…

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.830 DEBUG [x] 8 — [rading-events-1] o.f.c.e.impl.interceptor.LogInterceptor : — GetChannelModelCmd finished --------------------------------------------------------

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.831 DEBUG [x] 8 — [rading-events-1] o.f.c.e.impl.interceptor.LogInterceptor : — starting BaseEventRegistryEventConsumer$$Lambda$1260/0x00000001011b2840 --------------------------------------------------------

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.831 DEBUG [x] 8 — [rading-events-1] o.f.c.s.SpringTransactionInterceptor : Running command with propagation REQUIRED

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.831 DEBUG [x] 8 — [rading-events-1] o.f.c.engine.impl.agenda.AbstractAgenda : Operation class org.flowable.engine.impl.interceptor.CommandInvoker$1 added to agenda

Sep 1, 202123:12:21.885
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.831 DEBUG [x] 8 — [rading-events-1] o.f.e.impl.interceptor.CommandInvoker : Executing operation class org.flowable.engine.impl.interceptor.CommandInvoker$1

Sep 1, 202123:12:21.885
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.832 DEBUG [x] 8 — [rading-events-1] o.f.c.e.impl.interceptor.LogInterceptor : — starting EventSubscriptionQueryImpl --------------------------------------------------------

Sep 1, 202123:12:21.885
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.832 DEBUG [x] 8 — [rading-events-1] o.f.c.s.SpringTransactionInterceptor : Running command with propagation REQUIRED

Sep 1, 202123:12:21.885
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.832 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.i.CommandContextInterceptor : Valid context found. Reusing it for the current command ‘org.flowable.eventsubscription.service.impl.EventSubscriptionQueryImpl’

Sep 1, 202123:12:21.885
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.832 DEBUG [x] 8 — [rading-events-1] o.f.c.engine.impl.agenda.AbstractAgenda : Operation class org.flowable.engine.impl.interceptor.CommandInvoker$1 added to agenda

Se
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.832 DEBUG [x] 8 — [rading-events-1] o.f.e.impl.interceptor.CommandInvoker : Executing operation class org.flowable.engine.impl.interceptor.CommandInvoker$1

Sep 1, 202123:12:21.886
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.832 DEBUG [x] 8 — [rading-events-1] E.selectEventSubscriptionByQueryCriteria : ==> Preparing: select RES.* from ACT_RU_EVENT_SUBSCR RES WHERE RES.EVENT_TYPE_ = ? and RES.SCOPE_TYPE_ = ? and ( RES.CONFIGURATION_ in ( ? , ? , ? ) or RES.CONFIGURATION_ is null ) order by RES.ID_ asc

Sep 1, 202123:12:21.887
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.832 DEBUG [x] 8 — [rading-events-1] E.selectEventSubscriptionByQueryCriteria : ==> Parameters: urn:com:mutualofomaha:gpa:reconciliation:processed-count-completed(String), bpmn(String), 468bca81d2d1f408197cc1270da149b2(String), 90fdd649dc9da3dfeb75457bd2bf9e03(String), af51046f24910976f219bcd4115c425d(String)

Sep 1, 202123:12:21.887
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.833 DEBUG [x] 8 — [rading-events-1] E.selectEventSubscriptionByQueryCriteria : <== Total: 0

Sep 1, 202123:12:21.888
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.833 DEBUG [x] 8 — [rading-events-1] o.f.c.e.impl.interceptor.LogInterceptor : — EventSubscriptionQueryImpl finished --------------------------------------------------------

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.833 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : Flushing dbSqlSession

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.833 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : flush summary: 0 insert, 0 update, 0 delete.

Sep 1, 202123:12:21.888
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.833 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : now executing flush…

Sep 1, 202123:12:21.888
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.835 DEBUG [x] 8 — [rading-events-1] o.f.c.e.impl.interceptor.LogInterceptor : — BaseEventRegistryEventConsumer$$Lambda$1260/0x00000001011b2840 finished --------------------------------------------------------

Sep 1, 202123:12:21.888
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.835 DEBUG [x] 8 — [rading-events-1] o.f.c.e.impl.interceptor.LogInterceptor : — starting BaseEventRegistryEventConsumer$$Lambda$1260/0x00000001011b2840 --------------------------------------------------------

Sep 1, 202123:12:21.889
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.835 DEBUG [x] 8 — [rading-events-1] o.f.c.s.SpringTransactionInterceptor : Running command with propagation REQUIRED

Sep 1, 202123:12:21.889
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.836 DEBUG [x] 8 — [rading-events-1] o.f.c.engine.impl.agenda.AbstractAgenda : Operation class org.flowable.cmmn.engine.impl.interceptor.CmmnCommandInvoker$1 added to agenda

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.836 DEBUG [x] 8 — [rading-events-1] o.f.c.e.impl.interceptor.LogInterceptor : — starting EventSubscriptionQueryImpl --------------------------------------------------------

Sep 1, 202123:12:21.889
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.836 DEBUG [x] 8 — [rading-events-1] o.f.c.s.SpringTransactionInterceptor : Running command with propagation REQUIRED

Sep 1, 202123:12:21.890
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.836 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.i.CommandContextInterceptor : Valid context found. Reusing it for the current command ‘org.flowable.eventsubscription.service.impl.EventSubscriptionQueryImpl’

Sep 1, 202123:12:21.890
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.836 DEBUG [x] 8 — [rading-events-1] o.f.c.engine.impl.agenda.AbstractAgenda : Operation class org.flowable.cmmn.engine.impl.interceptor.CmmnCommandInvoker$1 added to agenda

Sep 1, 202123:12:21.890
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.836 DEBUG [x] 8 — [rading-events-1] E.selectEventSubscriptionByQueryCriteria : ==> Preparing: select RES.* from ACT_RU_EVENT_SUBSCR RES WHERE RES.EVENT_TYPE_ = ? and RES.SCOPE_TYPE_ = ? and ( RES.CONFIGURATION_ in ( ? , ? , ? ) or RES.CONFIGURATION_ is null ) order by RES.ID_ asc

Sep 1, 202123:12:21.893
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.839 DEBUG [x] 8 — [rading-events-1] o.f.c.s.SpringTransactionInterceptor : Running command with propagation REQUIRED

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.840 DEBUG [x] 8 — [rading-events-1] o.f.c.engine.impl.agenda.AbstractAgenda : Operation class org.flowable.cmmn.engine.impl.interceptor.CmmnCommandInvoker$1 added to agenda

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.840 DEBUG [x] 8 — [rading-events-1] tCaseInstanceEagerFetchPlanItemInstances : ==> Preparing: select C.*, P.ID_ as PI_ID_, P.REV_ as PI_REV_, P.CASE_DEF_ID_ as PI_CASE_DEF_ID_, P.DERIVED_CASE_DEF_ID_ as PI_DERIVED_CASE_DEF_ID_, P.CASE_INST_ID_ as PI_CASE_INST_ID_, P.STAGE_INST_ID_ as PI_STAGE_INST_ID_, P.IS_STAGE_ as PI_IS_STAGE_, P.ELEMENT_ID_ as PI_ELEMENT_ID_, P.ITEM_DEFINITION_ID_ as PI_ITEM_DEFINITION_ID_, P.ITEM_DEFINITION_TYPE_ as PI_ITEM_DEFINITION_TYPE_, P.NAME_ as PI_NAME_, P.STATE_ as PI_STATE_, P.CREATE_TIME_ as PI_CREATE_TIME_, P.LAST_AVAILABLE_TIME_ as PI_LAST_AVAILABLE_TIME_, P.LAST_ENABLED_TIME_ as PI_LAST_ENABLED_TIME_, P.LAST_DISABLED_TIME_ as PI_LAST_DISABLED_TIME_, P.LAST_STARTED_TIME_ as PI_LAST_STARTED_TIME_, P.LAST_SUSPENDED_TIME_ as PI_LAST_SUSPENDED_TIME_, P.COMPLETED_TIME_ as PI_COMPLETED_TIME_, P.OCCURRED_TIME_ as PI_OCCURRED_TIME_ , P.TERMINATED_TIME_ as PI_TERMINATED_TIME_, P.EXIT_TIME_ as PI_EXIT_TIME_, P.ENDED_TIME_ as PI_ENDED_TIME_, P.START_USER_ID_ as PI_USER_ID_, P.REFERENCE_ID_ as PI_REFERENCE_ID_, P.REFERENCE_TYPE_ as PI_REFERENCE_TYPE_, P.IS_COMPLETEABLE_ as PI_IS_COMPLETEABLE_, P.ENTRY_CRITERION_ID_ as PI_ENTRY_CRITERION_ID_, P.EXIT_CRITERION_ID_ as PI_EXIT_CRITERION_ID_, P.EXTRA_VALUE_ as PI_EXTRA_VALUE_, P.IS_COUNT_ENABLED_ as PI_IS_COUNT_ENABLED_, P.VAR_COUNT_ as PI_VAR_COUNT_, P.SENTRY_PART_INST_COUNT_ as PI_SENTRY_PART_INST_COUNT_, P.TENANT_ID_ as PI_TENANT_ID_, CASE_DEF.KEY_ as CaseDefinitionKey, CASE_DEF.NAME_ as CaseDefinitionName, CASE_DEF.VERSION_ as CaseDefinitionVersion, CASE_DEF.DEPLOYMENT_ID_ as CaseDefinitionDeploymentId from ACT_CMMN_RU_CASE_INST C inner join ACT_CMMN_CASEDEF CASE_DEF on C.CASE_DEF_ID_ = CASE_DEF.ID_ left join ACT_CMMN_RU_PLAN_ITEM_INST P on C.ID_ = CASE_INST_ID_ and P.ENDED_TIME_ is null WHERE C.ID_ = (select CASE_INST_ID_ from ACT_CMMN_RU_PLAN_ITEM_INST where ID_ = ?)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.840 DEBUG [x] 8 — [rading-events-1] tCaseInstanceEagerFetchPlanItemInstances : ==> Parameters: f489cdf0-0b6f-11ec-b72c-0242ac120017(String)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.843 DEBUG [x] 8 — [rading-events-1] tCaseInstanceEagerFetchPlanItemInstances : <== Total: 25

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.843 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.a.DefaultCmmnEngineAgenda : Planned [Trigger PlanItem] PlanItem ‘Plan Trade Confirm File Reconciliation’ (id: planItem3, definitionId: planTradeConfirmFileReconciliation)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.843 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.i.CmmnCommandInvoker : Executing agenda operation [Trigger PlanItem] PlanItem ‘Plan Trade Confirm File Reconciliation’ (id: planItem3, definitionId: planTradeConfirmFileReconciliation)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.843 DEBUG [x] 8 — [rading-events-1] e.E.selectEventSubscriptionsBySubScopeId : ==> Preparing: select * from ACT_RU_EVENT_SUBSCR where (SUB_SCOPE_ID_ = ?)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.843 DEBUG [x] 8 — [rading-events-1] e.E.selectEventSubscriptionsBySubScopeId : ==> Parameters: f489cdf0-0b6f-11ec-b72c-0242ac120017(String)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.844 DEBUG [x] 8 — [rading-events-1] e.E.selectEventSubscriptionsBySubScopeId : <== Total: 1

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.845 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.a.DefaultCmmnEngineAgenda : Planned [Occur plan item] PlanItem ‘Plan Trade Confirm File Reconciliation’ (id: planItem3, definitionId: planTradeConfirmFileReconciliation), new state: [completed] with transition [occur]

Sep 1, 202123:12:21.898
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.845 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.i.CmmnCommandInvoker : Executing agenda operation [Occur plan item] PlanItem ‘Plan Trade Confirm File Reconciliation’ (id: planItem3, definitionId: planTradeConfirmFileReconciliation), new state: [completed] with transition [occur]

Sep 1, 202123:12:21.898
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.845 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.a.DefaultCmmnEngineAgenda : Planned [Evaluate Criteria] case instance f429ad69-0b6f-11ec-b72c-0242ac120017 with transition ‘occur’ having fired for PlanItem ‘Plan Trade Confirm File Reconciliation’ (id: planItem3, definitionId: planTradeConfirmFileReconciliation)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.845 DEBUG [x] 8 — [rading-events-1] e.i.p.e.H.selectHistoricPlanItemInstance : ==> Preparing: select * from ACT_CMMN_HI_PLAN_ITEM_INST where ID_ = ?

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.845 DEBUG [x] 8 — [rading-events-1] e.i.p.e.H.selectHistoricPlanItemInstance : ==> Parameters: f489cdf0-0b6f-11ec-b72c-0242ac120017(String)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.846 DEBUG [x] 8 — [rading-events-1] e.i.p.e.H.selectHistoricPlanItemInstance : <== Total: 1

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.846 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.i.CmmnCommandInvoker : Executing agenda operation [Evaluate Criteria] case instance f429ad69-0b6f-11ec-b72c-0242ac120017 with transition ‘occur’ having fired for PlanItem ‘Plan Trade Confirm File Reconciliation’ (id: planItem3, definitionId: planTradeConfirmFileReconciliation)

Sep 1, 202123:12:21.899
2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.846 DEBUG [x] 8 — [rading-events-1] yCaseInstanceIdAndNullPlanItemInstanceId : ==> Preparing: select * from ACT_CMMN_RU_SENTRY_PART_INST where CASE_INST_ID_ = ? and PLAN_ITEM_INST_ID_ is null

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.846 DEBUG [x] 8 — [rading-events-1] yCaseInstanceIdAndNullPlanItemInstanceId : ==> Parameters: f429ad69-0b6f-11ec-b72c-0242ac120017(String)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.847 DEBUG [x] 8 — [rading-events-1] yCaseInstanceIdAndNullPlanItemInstanceId : <== Total: 1

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.847 DEBUG [x] 8 — [rading-events-1] ctSentryPartInstanceByPlanItemInstanceId : ==> Preparing: select * from ACT_CMMN_RU_SENTRY_PART_INST where PLAN_ITEM_INST_ID_ = ?

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.847 DEBUG [x] 8 — [rading-events-1] ctSentryPartInstanceByPlanItemInstanceId : ==> Parameters: f489cdf2-0b6f-11ec-b72c-0242ac120017(String)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] ctSentryPartInstanceByPlanItemInstanceId : <== Total: 2

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.a.o.EvaluateCriteriaOperation : Entry criterion with id ‘sid-D2364A3D-22A9-4E7A-AD40-436E2C8B466A’: onPart matches life cycle event [PlanItem lifecycle event for plan item [PlanItem ‘Plan Trade Confirm File Reconciliation’ (id: planItem3, definitionId: planTradeConfirmFileReconciliation)] and transition ‘occur’]

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.a.DefaultCmmnEngineAgenda : Planned [Evaluate Criteria] case instance f429ad69-0b6f-11ec-b72c-0242ac120017

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.i.CmmnCommandInvoker : Executing agenda operation [Evaluate Criteria] case instance f429ad69-0b6f-11ec-b72c-0242ac120017

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : Flushing dbSqlSession

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : insert org.flowable.cmmn.engine.impl.persistence.entity.SentryPartInstanceEntityImpl@2a2f54ed

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : update PlanItemInstance with id: f489cdf2-0b6f-11ec-b72c-0242ac120017, name: Plan Trade Confirm Milestone, definitionId: planTradeConfirmMilestone, state: available

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : update PlanItemInstance with id: f489cdf0-0b6f-11ec-b72c-0242ac120017, name: Plan Trade Confirm File Reconciliation, definitionId: planTradeConfirmFileReconciliation, state: completed

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : update org.flowable.cmmn.engine.impl.persistence.entity.HistoricPlanItemInstanceEntityImpl@5c66bb35

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : delete org.flowable.eventsubscription.service.impl.persistence.entity.GenericEventSubscriptionEntityImpl@26a0ffeb with id f489f52a-0b6f-11ec-b72c-0242ac120017

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : flush summary: 1 insert, 3 update, 1 delete.

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : now executing flush…

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : inserting: org.flowable.cmmn.engine.impl.persistence.entity.SentryPartInstanceEntityImpl@2a2f54ed

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.848 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.p.e.S.insertSentryPartInstance : ==> Preparing: insert into ACT_CMMN_RU_SENTRY_PART_INST (ID_, REV_, CASE_DEF_ID_, CASE_INST_ID_, PLAN_ITEM_INST_ID_, ON_PART_ID_, IF_PART_ID_, TIME_STAMP_) values ( ?, 1, ?, ?, ?, ?, ?, ? )

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.849 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.p.e.S.insertSentryPartInstance : ==> Parameters: f881e593-0ba3-11ec-97f5-0242ac12000e(String), db689751-eaef-11eb-8b93-0242ac120009(String), f429ad69-0b6f-11ec-b72c-0242ac120017(String), f489cdf2-0b6f-11ec-b72c-0242ac120017(String), sentryOnPart3(String), null, 2021-09-01 23:12:21.848(Timestamp)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.862 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.p.e.S.insertSentryPartInstance : <== Updates: 1

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.862 DEBUG [x] 8 — [rading-events-1] o.f.common.engine.impl.db.DbSqlSession : updating: PlanItemInstance with id: f489cdf2-0b6f-11ec-b72c-0242ac120017, name: Plan Trade Confirm Milestone, definitionId: planTradeConfirmMilestone, state: available

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.862 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.p.e.P.updatePlanItemInstance : ==> Preparing: update ACT_CMMN_RU_PLAN_ITEM_INST SET REV_ = ?, IS_COMPLETEABLE_ = ?, SENTRY_PART_INST_COUNT_ = ? where ID_ = ? and REV_ = ?

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.862 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.p.e.P.updatePlanItemInstance : ==> Parameters: 4(Integer), false(Boolean), 3(Integer), f489cdf2-0b6f-11ec-b72c-0242ac120017(String), 3(Integer)

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.863 DEBUG [x] 8 — [rading-events-1] o.f.c.e.i.p.e.P.updatePlanItemInstance : <== Updates: 0

2021-09-01T23:12:21-05:00 w 44491 - - 2021-09-01 23:12:21.875 DEBUG [x] 8 — [rading-events-1] o.f.c.e.impl.interceptor.LogInterceptor : — TriggerPlanItemInstanceCmd finished --------------------------------------------------------

tjmac44 · September 3, 2021, 12:10pm

This above trace was a different event that also fails intermittently. It results in this database query in the ACT_CMMN_HI_PLAN_ITEM_INST is state terminated as the case was closed by a timer. I would be expecting the state to be completed.

select * from ACT_CMMN_HI_PLAN_ITEM_INST p where p.CASE_INST_ID_ = ‘f429ad69-0b6f-11ec-b72c-0242ac120017’ and p.NAME_ = ‘Plan Trade Confirm File Reconciliation’

f489cdf0-0b6f-11ec-b72c-0242ac120017
2
Plan Trade Confirm File Reconciliation
terminated
db689751-eaef-11eb-8b93-0242ac120009
f429ad69-0b6f-11ec-b72c-0242ac120017
f486255a-0b6f-11ec-b72c-0242ac120017
false
planItem3
planTradeConfirmFileReconciliation
genericeventlistener
2021-09-01 17:00:01.360
2021-09-01 17:00:01.360
NULL
NULL
NULL
NULL
NULL
NULL
NULL
2021-09-02 13:00:07.317
2021-09-02 13:00:07.317
2021-09-02 13:00:07.317
NULL
NULL
NULL
NULL
NULL
false
NULL
NULL
NULL

Topic		Replies	Views
Event registry peculiarities Flowable Engine	4	1262	May 11, 2020
Message event problem Flowable Engine	6	518	June 15, 2020
Event Registry - Springboot Starter	4	539	March 25, 2020
Event register problem	9	586	November 23, 2020
Event Registry Boundary Event not working Flowable Engine	8	676	November 9, 2020

Event Registry intermittent not correlating event

Related topics