QA: Synchronize client and broker in tests #30
Assignees
Comments
ghost
pushed a commit
that referenced
this issue
Mar 31, 2021
6701: Improve compact log for rejections and error records r=saig0 a=saig0 ## Description * log rejections in the same way as commands and events * provide more data for root causing a rejection (e.g. value type, intent, position, etc.) * add summarize for error records * shrink the terms with `INSTANCE` -> `INST` and `VARIABLE` -> `VAR` * remove the term `ELEMENT` completely because it is too verbose and redundant (every activate/activating/activated etc. belongs to elements) <details><summary>Current output</summary> <p> ``` 07:43:02.648 [] INFO io.zeebe.test - Compact log representation: -------- ['C'ommand/'E'event/'R'ejection] [valueType] [intent] - #[position]->#[source record position] P[partitionId]K[key] - [summary of value] P9K999 - key; #999 - record position; "ID" element/process id; @"elementid"/[P9K999] - element with ID and key Keys are decomposed into partition id and per partition key (e.g. 2251799813685253 -> P1K005). If single partition, the partition is omitted. Long IDs are shortened (e.g. 'startEvent_5d56488e-0570-416c-ba2d-36d2a3acea78' -> 'star..acea78' -------- C DEPLOYMENT CREATE - #1-> -1 -1 - process.xml E PROC CREATED - #2->#1 K01 - process.xml->"process" (version:1) E DEPLOYMENT CREATED - #3->#1 K02 - process.xml E DEPLOYMENT FULLY_DISTR - #4->#1 K02 - C MSG PUBLISH - #5-> -1 -1 - "msg1" correlationKey: order-123 (no vars) E MSG PUBLISHED - #6->#5 K03 - "msg1" correlationKey: order-123 (no vars) C PROC_INSTANCE_CREATION CREATE - #7-> -1 -1 - new <process "process"> with variables: {key=order-123} E VARIABLE CREATED - #8->#7 K05 - key->"order-123" in <process [K04]> E PROC_INSTANCE ELMNT_ACTIVATING - #9->#7 K04 - PROCESS "process" in <process "process"[K04]> E PROC_INSTANCE_CREATION CREATED - #10->#7 K06 - new <process "process"> with variables: {key=order-123} E PROC_INSTANCE ELMNT_ACTIVATED - #11->#9 K04 - PROCESS "process" in <process "process"[K04]> E PROC_INSTANCE ELMNT_ACTIVATING - #12->#11 K07 - START_EVENT "startEv..323d1cb" in <process "process"[K04]> E PROC_INSTANCE ELMNT_ACTIVATED - #13->#12 K07 - START_EVENT "startEv..323d1cb" in <process "process"[K04]> E PROC_INSTANCE ELMNT_COMPLETING - #14->#13 K07 - START_EVENT "startEv..323d1cb" in <process "process"[K04]> E PROC_INSTANCE ELMNT_COMPLETED - #15->#14 K07 - START_EVENT "startEv..323d1cb" in <process "process"[K04]> E PROC_INSTANCE SEQ_FLOW_TAKEN - #16->#15 K08 - SEQUENCE_FLOW "sequenc..8cfbcaa" in <process "process"[K04]> C PROC_INSTANCE ACTIVATE_ELMNT - #17->#16 K09 - RECEIVE_TASK "task" in <process "process"[K04]> E PROC_INSTANCE ELMNT_ACTIVATING - #18->#17 K09 - RECEIVE_TASK "task" in <process "process"[K04]> E PROC_MSG_SUB CREATING - #19->#17 -1 - "taskMsg" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) E PROC_MSG_SUB CREATING - #20->#17 -1 - "msg2" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) E PROC_MSG_SUB CREATING - #21->#17 -1 - "msg1" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) E PROC_INSTANCE ELMNT_ACTIVATED - #22->#17 K09 - RECEIVE_TASK "task" in <process "process"[K04]> C MSG_SUB CREATE - #23-> -1 -1 - "taskMsg" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) C MSG_SUB CREATE - #24-> -1 -1 - "msg2" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) C MSG_SUB CREATE - #25-> -1 -1 - "msg1" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) E MSG_SUB CREATED - #26->#23 K10 - "taskMsg" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) C PROC_MSG_SUB CREATE - #27-> -1 -1 - "taskMsg" (inter.) @[K09] in <process ?> (no vars) E MSG_SUB CREATED - #28->#24 K11 - "msg2" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) C PROC_MSG_SUB CREATE - #29-> -1 -1 - "msg2" (inter.) @[K09] in <process ?> (no vars) E MSG_SUB CREATED - #30->#25 K12 - "msg1" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) E MSG_SUB CORRELATING - #31->#25 K12 - "msg1" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) C PROC_MSG_SUB CORRELATE - #32-> -1 -1 - "msg1" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) E PROC_MSG_SUB CREATED - #33->#27 -1 - "taskMsg" (inter.) @[K09] in <process ?> (no vars) E PROC_MSG_SUB CREATED - #34->#29 -1 - "msg2" (inter.) @[K09] in <process ?> (no vars) E PROC_MSG_SUB CORRELATED - #35->#32 -1 - "msg1" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) C PROC_INSTANCE ACTIVATE_ELMNT - #36->#32 -1 - RECEIVE_TASK "task" in <process "process"[K04]> C MSG_SUB CORRELATE - #37-> -1 -1 - "msg1" (inter.) @[K09] in <process "process"[K04]> (no vars) PROCESSING_ERROR Expected to process event 'TypedEventImpl{metadata=RecordMetadata{recordType=COMMAND, intentValue=255, intent=ACTIVATE_ELEMENT, requestStreamId=-2147483648, requestId=-1, protocolVersion=3, valueType=PROCESS_INSTANCE, rejectionType=NULL_VAL, rejectionReason=, brokerVersion=1.0.0}, value={"bpmnProcessId":"process","version":1,"processDefinitionKey":2251799813685249,"processInstanceKey":2251799813685252,"elementId":"task","flowScopeKey":2251799813685252,"bpmnElementType":"RECEIVE_TASK","parentProcessInstanceKey":-1,"parentElementInstanceKey":-1}}' without errors, but exception occurred with message 'Not expected to have an active sequence flow count lower then zero!'.#38->#36 -1 - E ERROR CREATED - #39->#36 -1 - ErrorRecord {"stacktrace":"java.lang.IllegalStateException: Not expected to have an active sequence flow count lower then zero!\n\tat io.zeebe.engine.state.instance.ElementInstance.decrementActiveSequenceFlows(ElementInstance.java:168)\n\tat io.zeebe.engine.state.appliers.ProcessInstanceElementActivatingApplier.decrementActiveSequenceFlow(ProcessInstanceElementActivatingApplier.java:108)\n\tat io.zeebe.engine.state.appliers.ProcessInstanceElementActivatingApplier.applyState(ProcessInstanceElementActivatingApplier.java:62)\n\tat io.zeebe.engine.state.appliers.ProcessInstanceElementActivatingApplier.applyState(ProcessInstanceElementActivatingApplier.java:26)\n\tat io.zeebe.engine.state.appliers.EventAppliers.applyState(EventAppliers.java:217)\n\tat io.zeebe.engine.processing.streamprocessor.writers.EventApplyingStateWriter.appendFollowUpEvent(EventApplyingStateWriter.java:49)\n\tat io.zeebe.engine.processing.streamprocessor.writers.EventApplyingStateWriter.appendFollowUpEvent(EventApplyingStateWriter.java:39)\n\tat io.zeebe.engine.processing.bpmn.behavior.BpmnStateTransitionBehavior.transitionTo(BpmnStateTransitionBehavior.java:216)\n\tat io.zeebe.engine.processing.bpmn.behavior.BpmnStateTransitionBehavior.transitionToActivating(BpmnStateTransitionBehavior.java:103)\n\tat io.zeebe.engine.processing.bpmn.BpmnStreamProcessor.processEvent(BpmnStreamProcessor.java:146)\n\tat io.zeebe.engine.processing.bpmn.BpmnStreamProcessor.processRecord(BpmnStreamProcessor.java:134)\n\tat io.zeebe.engine.processing.streamprocessor.TypedRecordProcessor.processRecord(TypedRecordProcessor.java:54)\n\tat io.zeebe.engine.processing.streamprocessor.ProcessingStateMachine.lambda$processInTransaction$3(ProcessingStateMachine.java:296)\n\tat io.zeebe.db.impl.rocksdb.transaction.ZeebeTransaction.run(ZeebeTransaction.java:84)\n\tat io.zeebe.engine.processing.streamprocessor.ProcessingStateMachine.processInTransaction(ProcessingStateMachine.java:286)\n\tat io.zeebe.engine.processing.streamprocessor.ProcessingStateMachine.processEvent(ProcessingStateMachine.java:254)\n\tat io.zeebe.engine.processing.streamprocessor.ProcessingStateMachine.tryToReadNextEvent(ProcessingStateMachine.java:219)\n\tat io.zeebe.engine.processing.streamprocessor.ProcessingStateMachine.readNextEvent(ProcessingStateMachine.java:210)\n\tat io.zeebe.util.sched.ActorJob.invoke(ActorJob.java:73)\n\tat io.zeebe.util.sched.ActorJob.execute(ActorJob.java:39)\n\tat io.zeebe.util.sched.ActorTask.execute(ActorTask.java:122)\n\tat io.zeebe.util.sched.ActorThread.executeCurrentTask(ActorThread.java:94)\n\tat io.zeebe.util.sched.ActorThread.doWork(ActorThread.java:78)\n\tat io.zeebe.util.sched.ActorThread.run(ActorThread.java:191)\n","processInstanceKey":2251799813685252,"exceptionMessage":"Not expected to have an active sequence flow count lower then zero!","errorEventPosition":36} -------- Decomposed keys (for debugging): -1 <-> -1 K01 <-> 2251799813685249 K02 <-> 2251799813685250 K03 <-> 2251799813685251 K04 <-> 2251799813685252 K05 <-> 2251799813685253 K06 <-> 2251799813685254 K07 <-> 2251799813685255 K08 <-> 2251799813685256 K09 <-> 2251799813685257 K10 <-> 2251799813685258 K11 <-> 2251799813685259 K12 <-> 2251799813685260 ``` <p> </details> <details><summary>Output with the changes</summary> <p> ``` 07:38:03.861 [] INFO io.zeebe.test - Compact log representation: -------- ['C'ommand/'E'event/'R'ejection] [valueType] [intent] - #[position]->#[source record position] P[partitionId]K[key] - [summary of value] P9K999 - key; #999 - record position; "ID" element/process id; @"elementid"/[P9K999] - element with ID and key Keys are decomposed into partition id and per partition key (e.g. 2251799813685253 -> P1K005). If single partition, the partition is omitted. Long IDs are shortened (e.g. 'startEvent_5d56488e-0570-416c-ba2d-36d2a3acea78' -> 'star..acea78' -------- C DEPLOYMENT CREATE - #1-> -1 -1 - process.xml E PROC CREATED - #2->#1 K01 - process.xml->"process" (version:1) E DEPLOYMENT CREATED - #3->#1 K02 - process.xml E DEPLOYMENT FULLY_DISTR - #4->#1 K02 - C MSG PUBLISH - #5-> -1 -1 - "msg1" correlationKey: order-123 (no vars) E MSG PUBLISHED - #6->#5 K03 - "msg1" correlationKey: order-123 (no vars) C PROC_INST_CREATION CREATE - #7-> -1 -1 - new <process "process"> with variables: {key=order-123} E VAR CREATED - #8->#7 K05 - key->"order-123" in <process [K04]> E PROC_INST ACTIVATING - #9->#7 K04 - PROCESS "process" in <process "process"[K04]> E PROC_INST_CREATION CREATED - #10->#7 K06 - new <process "process"> with variables: {key=order-123} E PROC_INST ACTIVATED - #11->#9 K04 - PROCESS "process" in <process "process"[K04]> E PROC_INST ACTIVATING - #12->#11 K07 - START_EVENT "startEv..b233ada" in <process "process"[K04]> E PROC_INST ACTIVATED - #13->#12 K07 - START_EVENT "startEv..b233ada" in <process "process"[K04]> E PROC_INST COMPLETING - #14->#13 K07 - START_EVENT "startEv..b233ada" in <process "process"[K04]> E PROC_INST COMPLETED - #15->#14 K07 - START_EVENT "startEv..b233ada" in <process "process"[K04]> E PROC_INST SEQ_FLOW_TAKEN - #16->#15 K08 - SEQUENCE_FLOW "sequenc..fb40cc7" in <process "process"[K04]> C PROC_INST ACTIVATE - #17->#16 K09 - RECEIVE_TASK "task" in <process "process"[K04]> E PROC_INST ACTIVATING - #18->#17 K09 - RECEIVE_TASK "task" in <process "process"[K04]> E PROC_MSG_SUB CREATING - #19->#17 -1 - "taskMsg" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) E PROC_MSG_SUB CREATING - #20->#17 -1 - "msg2" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) E PROC_MSG_SUB CREATING - #21->#17 -1 - "msg1" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) E PROC_INST ACTIVATED - #22->#17 K09 - RECEIVE_TASK "task" in <process "process"[K04]> C MSG_SUB CREATE - #23-> -1 -1 - "taskMsg" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) C MSG_SUB CREATE - #24-> -1 -1 - "msg2" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) C MSG_SUB CREATE - #25-> -1 -1 - "msg1" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) E MSG_SUB CREATED - #26->#23 K10 - "taskMsg" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) C PROC_MSG_SUB CREATE - #27-> -1 -1 - "taskMsg" (inter.) @[K09] in <process ?[K04]> (no vars) E MSG_SUB CREATED - #28->#24 K11 - "msg2" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) C PROC_MSG_SUB CREATE - #29-> -1 -1 - "msg2" (inter.) @[K09] in <process ?[K04]> (no vars) E MSG_SUB CREATED - #30->#25 K12 - "msg1" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) E MSG_SUB CORRELATING - #31->#25 K12 - "msg1" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) C PROC_MSG_SUB CORRELATE - #32-> -1 -1 - "msg1" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) E PROC_MSG_SUB CREATED - #33->#27 -1 - "taskMsg" (inter.) @[K09] in <process ?[K04]> (no vars) E PROC_MSG_SUB CREATED - #34->#29 -1 - "msg2" (inter.) @[K09] in <process ?[K04]> (no vars) E PROC_MSG_SUB CORRELATED - #35->#32 -1 - "msg1" (inter.) correlationKey: order-123 @[K09] in <process "process"[K04]> (no vars) C PROC_INST ACTIVATE - #36->#32 -1 - RECEIVE_TASK "task" in <process "process"[K04]> C MSG_SUB CORRELATE - #37-> -1 -1 - "msg1" (inter.) @[K09] in <process "process"[K04]> (no vars) R PROC_INST ACTIVATE - #38->#36 -1 - RECEIVE_TASK "task" in <process "process"[K04]> !PROCESSING_ERROR (Expected to process event 'TypedEventImpl{metadata=RecordMetadata{recordType=COMMAND, intentValue=..) E ERROR CREATED - #39->#36 -1 - "Not expected to have an active sequence flow count lower then zero!" in <process ?[K04]> (java.lang.IllegalStateException: Not expected to have an active sequence flow count lower then zer..) -------- Decomposed keys (for debugging): -1 <-> -1 K01 <-> 2251799813685249 K02 <-> 2251799813685250 K03 <-> 2251799813685251 K04 <-> 2251799813685252 K05 <-> 2251799813685253 K06 <-> 2251799813685254 K07 <-> 2251799813685255 K08 <-> 2251799813685256 K09 <-> 2251799813685257 K10 <-> 2251799813685258 K11 <-> 2251799813685259 K12 <-> 2251799813685260 ``` <p> </details> _The most changes happened on the last two records._ ## Related issues ## Definition of Done _Not all items need to be done depending on the issue and the pull request._ Code changes: * [ ] The changes are backwards compatibility with previous versions * [ ] If it fixes a bug then PRs are created to [backport](https://github.com/zeebe-io/zeebe/compare/stable/0.24...develop?expand=1&template=backport_template.md&title=[Backport%200.24]) the fix to the last two minor versions. You can trigger a backport by assigning labels (e.g. `backport stable/0.25`) to the PR, in case that fails you need to create backports manually. Testing: * [ ] There are unit/integration tests that verify all acceptance criterias of the issue * [ ] New tests are written to ensure backwards compatibility with further versions * [ ] The behavior is tested manually * [ ] The change has been verified by a QA run * [ ] The impact of the changes is verified by a benchmark Documentation: * [ ] The documentation is updated (e.g. BPMN reference, configuration, examples, get-started guides, etc.) * [ ] New content is added to the [release announcement](https://drive.google.com/drive/u/0/folders/1DTIeswnEEq-NggJ25rm2BsDjcCQpDape) Co-authored-by: Philipp Ossler <philipp.ossler@gmail.com>
9 tasks
ghost
pushed a commit
that referenced
this issue
Feb 28, 2022
8843: test(test-util): summarize DMN records r=saig0 a=saig0 ## Description * extend the compact logger that is mainly used to print the records when a test failed * display DMN resources of deployment record * summarize decision requirements and decision records * summarize decision evaluation records Before: ``` C DEPLOYMENT CREATE - #1-> -1 -1 - E DECISION_REQUIREMENTS CREATED - #2->#1 K01 - DecisionRequirementsRecord {"resource":"PD94bWwgdmVyc2lvbj0iMS4wIiBlbmNvZGluZz0iVVRGLTgiPz4KPG...","decisionRequirementsKey":2251799813685249,"decisionRequirementsId":"force_users","resourceName":"/dmn/drg-force-user.dmn","checksum":"4CVEZphbvJhEHAY8+PoEbw==","decisionRequirementsName":"force_users","decisionRequirementsVersion":1,"namespace":"http://camunda.org/schema/1.0/dmn","duplicate":false} E DECISION CREATED - #3->#1 K02 - DecisionRecord {"version":1,"decisionKey":2251799813685250,"decisionId":"jedi_or_sith","decisionName":"Jedi or Sith","decisionRequirementsKey":2251799813685249,"decisionRequirementsId":"force_users","duplicate":false} E DECISION CREATED - #4->#1 K03 - DecisionRecord {"version":1,"decisionKey":2251799813685251,"decisionId":"force_user","decisionName":"Which force user?","decisionRequirementsKey":2251799813685249,"decisionRequirementsId":"force_users","duplicate":false} E PROC CREATED - #5->#1 K04 - process.xml -> "process" (version:1) E DEPLOYMENT CREATED - #6->#1 K05 - process.xml E DEPLOYMENT FULLY_DISTR - #7->#1 K05 - ... E DECISION_EVALUATION EVALUATED - #24->#22 K13 - DecisionEvaluationRecord {"decisionKey":2251799813685251,"decisionId":"force_user","decisionName":"Which force user?","decisionRequirementsKey":2251799813685249,"decisionRequirementsId":"force_users","processDefinitionKey":2251799813685252,"bpmnProcessId":"process","processInstanceKey":2251799813685254,"elementId":"task","evaluatedDecisions":[{"decisionKey":2251799813685250,"decisionId":"jedi_or_sith","decisionName":"Jedi or Sith","evaluatedInputs":[{"inputId":"Input_1","inputName":"Lightsaber color","inputValue":"\"blue\""}],"matchedRules":[{"evaluatedOutputs":[{"outputId":"Output_1","outputName":"jedi_or_sith","outputValue":"\"Jedi\""}],"ruleId":"DecisionRule_0zumznl","ruleIndex":1}],"decisionType":"DECISION_TABLE","decisionOutput":"\"Jedi\""},{"decisionKey":2251799813685251,"decisionId":"force_user","decisionName":"Which force user?","evaluatedInputs":[{"inputId":"InputClause_0qnqj25","inputName":"Jedi or Sith","inputValue":"\"Jedi\""},{"inputId":"InputClause_0k64hys","inputName":"Body height","inputValue":"182"}],"matchedRules":[{"evaluatedOutputs":[{"outputId":"OutputClause_0hhe1yo","outputName":"force_user","outputValue":"\"Obi-Wan Kenobi\""}],"ruleId":"DecisionRule_0uin2hk","ruleIndex":2}],"decisionType":"DECISION_TABLE","decisionOutput":"\"Obi-Wan Kenobi\""}],"decisionOutput":"\"Obi-Wan Kenobi\"","elementInstanceKey":2251799813685260,"decisionVersion":1,"evaluationFailureMessage":"","failedDecisionId":""} ``` After: ``` C DEPLOYMENT CREATE - #1-> -1 -1 - E DRG CREATED - #2->#1 K01 - /dmn/drg-force-user.dmn -> "force_users" (version:1) E DECISION CREATED - #3->#1 K02 - "jedi_or_sith" (version:1) of <drg "force_users"[K01]> E DECISION CREATED - #4->#1 K03 - "force_user" (version:1) of <drg "force_users"[K01]> E PROC CREATED - #5->#1 K04 - process.xml -> "process" (version:1) E DEPLOYMENT CREATED - #6->#1 K05 - process.xml, /dmn/drg-force-user.dmn E DEPLOYMENT FULLY_DISTR - #7->#1 K05 - ... E DECISION_EVAL EVALUATED - #24->#22 K13 - "Obi-Wan Kenobi" of <decision "force_user"[K03]> in <process "process"[K06]> @"task"[K12] ``` <details> <summary>Full test output</summary> <pre> C DEPLOYMENT CREATE - #1-> -1 -1 - E DRG CREATED - #2->#1 K01 - /dmn/drg-force-user.dmn -> "force_users" (version:1) E DECISION CREATED - #3->#1 K02 - "jedi_or_sith" (version:1) of <drg "force_users"[K01]> E DECISION CREATED - #4->#1 K03 - "force_user" (version:1) of <drg "force_users"[K01]> E PROC CREATED - #5->#1 K04 - process.xml -> "process" (version:1) E DEPLOYMENT CREATED - #6->#1 K05 - process.xml, /dmn/drg-force-user.dmn E DEPLOYMENT FULLY_DISTR - #7->#1 K05 - C PROC_INST_CREATION CREATE - #8-> -1 -1 - new <process "process"> with variables: {lightsaberColor=blue, height=182} E VAR CREATED - #9->#8 K07 - height->182 in <process [K06]> E VAR CREATED - #10->#8 K08 - lightsaberColor->"blue" in <process [K06]> C PROC_INST ACTIVATE - #11->#8 K06 - PROCESS "process" in <process "process"[K06]> E PROC_INST_CREATION CREATED - #12->#8 K09 - new <process "process"> with variables: {lightsaberColor=blue, height=182} E PROC_INST ACTIVATING - #13->#11 K06 - PROCESS "process" in <process "process"[K06]> E PROC_INST ACTIVATED - #14->#11 K06 - PROCESS "process" in <process "process"[K06]> C PROC_INST ACTIVATE - #15->#11 -1 - START_EVENT "startEv..29dbbd9" in <process "process"[K06]> E PROC_INST ACTIVATING - #16->#15 K10 - START_EVENT "startEv..29dbbd9" in <process "process"[K06]> E PROC_INST ACTIVATED - #17->#15 K10 - START_EVENT "startEv..29dbbd9" in <process "process"[K06]> C PROC_INST COMPLETE - #18->#15 K10 - START_EVENT "startEv..29dbbd9" in <process "process"[K06]> E PROC_INST COMPLETING - #19->#18 K10 - START_EVENT "startEv..29dbbd9" in <process "process"[K06]> E PROC_INST COMPLETED - #20->#18 K10 - START_EVENT "startEv..29dbbd9" in <process "process"[K06]> E PROC_INST SEQ_FLOW_TAKEN - #21->#18 K11 - SEQUENCE_FLOW "sequenc..272f6f6" in <process "process"[K06]> C PROC_INST ACTIVATE - #22->#18 K12 - BUSINESS_RULE_TASK "task" in <process "process"[K06]> E PROC_INST ACTIVATING - #23->#22 K12 - BUSINESS_RULE_TASK "task" in <process "process"[K06]> E DECISION_EVAL EVALUATED - #24->#22 K13 - "Obi-Wan Kenobi" of <decision "force_user"[K03]> in <process "process"[K06]> @"task"[K12] E PROC_EVNT TRIGGERING - #25->#22 K14 - @"task"[K12] in <process K04[K06]> with variables: {result=Obi-Wan Kenobi} E PROC_INST ACTIVATED - #26->#22 K12 - BUSINESS_RULE_TASK "task" in <process "process"[K06]> C PROC_INST COMPLETE - #27->#22 K12 - BUSINESS_RULE_TASK "task" in <process "process"[K06]> E PROC_INST COMPLETING - #28->#27 K12 - BUSINESS_RULE_TASK "task" in <process "process"[K06]> E VAR CREATED - #29->#27 K15 - result->"Obi-Wan Kenobi" in <process [K06]> E PROC_INST COMPLETED - #30->#27 K12 - BUSINESS_RULE_TASK "task" in <process "process"[K06]> C PROC_INST COMPLETE - #31->#27 K06 - PROCESS "process" in <process "process"[K06]> E PROC_INST COMPLETING - #32->#31 K06 - PROCESS "process" in <process "process"[K06]> E PROC_INST COMPLETED - #33->#31 K06 - PROCESS "process" in <process "process"[K06]> </pre> </details> ## Related issues None. Co-authored-by: Philipp Ossler <philipp.ossler@gmail.com>
zeebe-bors-camunda bot
added a commit
that referenced
this issue
May 9, 2023
12697: Fix flaky `EmbeddedSubProcessTest` r=koevskinikola a=remcowesterhoud ## Description <!-- Please explain the changes you made here. --> The test was flaky because it could occur that the messages got published before the subscription were opened. As the messages have no TTL this means they were not getting correlated, as expected. Log of a failing run: ``` C DPLY CREATE - #1-> -1 -1 - E PROC CREATED - #2->#1 K01 - process.xml -> "process..process" (version:1) E DPLY CREATED - #3->#1 K02 - process.xml E DPLY FULLY_DISTRIBUTED - #4->#1 K02 - C CREA CREATE - #5-> -1 -1 - new <process "process..process"> with variables: {correlationKey=correlationKey} E VAR CREATED - #6->#5 K04 - correlationKey->"correlationKey" in <process [K03]> C PI ACTIVATE - #7->#5 K03 - PROCESS "process..process" in <process "process..process"[K03]> E CREA CREATED - #8->#5 K05 - new <process "process..process"> with variables: {correlationKey=correlationKey} E PI ACTIVATING - #9->#7 K03 - PROCESS "process..process" in <process "process..process"[K03]> E PI ACTIVATED - #10->#7 K03 - PROCESS "process..process" in <process "process..process"[K03]> C PI ACTIVATE - #11->#7 -1 - START_EVENT "startEv..8897acc" in <process "process..process"[K03]> E PI ACTIVATING - #12->#11 K06 - START_EVENT "startEv..8897acc" in <process "process..process"[K03]> E PI ACTIVATED - #13->#11 K06 - START_EVENT "startEv..8897acc" in <process "process..process"[K03]> C PI COMPLETE - #14->#11 K06 - START_EVENT "startEv..8897acc" in <process "process..process"[K03]> E PI COMPLETING - #15->#14 K06 - START_EVENT "startEv..8897acc" in <process "process..process"[K03]> E PROC_MSG_SUB CREATING - #16->#14 K07 - "eventSubProcess" (inter.) correlationKey: correlationKey `@[K03]` in <process "process..process"[K03]> (no vars) E PI COMPLETED - #17->#14 K06 - START_EVENT "startEv..8897acc" in <process "process..process"[K03]> E PI SEQ_FLOW_TAKEN - #18->#14 K08 - SEQUENCE_FLOW "sequenc..b7cb1a6" in <process "process..process"[K03]> C PI ACTIVATE - #19->#14 K09 - SUB_PROCESS "subProcess" in <process "process..process"[K03]> E PI ACTIVATING - #20->#19 K09 - SUB_PROCESS "subProcess" in <process "process..process"[K03]> E PI ACTIVATED - #21->#19 K09 - SUB_PROCESS "subProcess" in <process "process..process"[K03]> C PI ACTIVATE - #22->#19 -1 - START_EVENT "startEv..8b12a7c" in <process "process..process"[K03]> E PI ACTIVATING - #23->#22 K10 - START_EVENT "startEv..8b12a7c" in <process "process..process"[K03]> E PI ACTIVATED - #24->#22 K10 - START_EVENT "startEv..8b12a7c" in <process "process..process"[K03]> C PI COMPLETE - #25->#22 K10 - START_EVENT "startEv..8b12a7c" in <process "process..process"[K03]> E PI COMPLETING - #26->#25 K10 - START_EVENT "startEv..8b12a7c" in <process "process..process"[K03]> E PROC_MSG_SUB CREATING - #27->#25 K11 - "boundary" (inter.) correlationKey: correlationKey `@[K09]` in <process "process..process"[K03]> (no vars) E PI COMPLETED - #28->#25 K10 - START_EVENT "startEv..8b12a7c" in <process "process..process"[K03]> E PI SEQ_FLOW_TAKEN - #29->#25 K12 - SEQUENCE_FLOW "sequenc..8c72ad0" in <process "process..process"[K03]> C PI ACTIVATE - #30->#25 K13 - SERVICE_TASK "task" in <process "process..process"[K03]> E PI ACTIVATING - #31->#30 K13 - SERVICE_TASK "task" in <process "process..process"[K03]> E JOB CREATED - #32->#30 K14 - K14 "task" `@"task"[K13]` 3 retries, in <process "process..process"[K03]> (no vars) E PI ACTIVATED - #33->#30 K13 - SERVICE_TASK "task" in <process "process..process"[K03]> C MSG PUBLISH - #34-> -1 K01 - "boundary" correlationKey: correlationKey (no vars) C MSG PUBLISH - #35-> -1 K01 - "eventSubProcess" correlationKey: correlationKey (no vars) E MSG PUBLISHED - #36->#34 K15 - "boundary" correlationKey: correlationKey (no vars) E MSG EXPIRED - #37->#34 K15 - "boundary" correlationKey: correlationKey (no vars) E MSG PUBLISHED - #38->#35 K16 - "eventSubProcess" correlationKey: correlationKey (no vars) E MSG EXPIRED - #39->#35 K16 - "eventSubProcess" correlationKey: correlationKey (no vars) C MSG_SUB CREATE - #40-> -1 -1 - "eventSubProcess" (inter.) correlationKey: correlationKey `@[K03]` in <process "process..process"[K03]> (no vars) C MSG_SUB CREATE - #41-> -1 -1 - "boundary" (inter.) correlationKey: correlationKey `@[K09]` in <process "process..process"[K03]> (no vars) E MSG_SUB CREATED - #42->#40 K17 - "eventSubProcess" (inter.) correlationKey: correlationKey `@[K03]` in <process "process..process"[K03]> (no vars) C PROC_MSG_SUB CREATE - #43-> -1 -1 - "eventSubProcess" (inter.) `@[K03]` in <process ?[K03]> (no vars) E MSG_SUB CREATED - #44->#41 K18 - "boundary" (inter.) correlationKey: correlationKey `@[K09]` in <process "process..process"[K03]> (no vars) C PROC_MSG_SUB CREATE - #45-> -1 -1 - "boundary" (inter.) `@[K09]` in <process ?[K03]> (no vars) E PROC_MSG_SUB CREATED - #46->#43 K07 - "eventSubProcess" (inter.) correlationKey: correlationKey `@[K03]` in <process "process..process"[K03]> (no vars) E PROC_MSG_SUB CREATED - #47->#45 K11 - "boundary" (inter.) correlationKey: correlationKey `@[K09]` in <process "process..process"[K03]> (no vars) ``` The test isn't really flaky on 8.2+ anymore. This is a result of batch processing that was introduced recently. However, I believe it's still good to fix it on all versions and keep the test aligned across versions. ## Related issues <!-- Which issues are closed by this PR or are related --> closes #11844 Co-authored-by: Remco Westerhoud <remco@westerhoud.nl>
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Client and broker are asynchronous by design.
In test cases, we want a certain synchronization, for example that the client does make a certain request only when the broker has reached a certain state.
The text was updated successfully, but these errors were encountered: