Test Deploy Bpmn Process Request Handler #2
Assignees
Comments
meyerdan
changed the title
meyerdan
changed the title
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
Aug 15, 2022
10073: Abbreviate Deployment Distribution records in compact logger r=pihme a=korthout ## Description <!-- Please explain the changes you made here. --> Many record types are abbreviated in the compact logger, but some of the more common (and also longer) ones aren't. See for example, this output after a failed test: ``` 2 C DEPLOYMENT DISTRIBUTE - #1->-1 P1K2 - process.xml 3 C DEPLOYMENT DISTRIBUTE - #1->-1 P1K2 - process.xml 1 C DEPLOYMENT CREATE - #1->-1 -1 - 1 E PROC CREATED - #2->#1 P1K1 - process.xml -> "shouldR..ecovery" (version:1) 1 E DEPLOYMENT CREATED - #3->#1 P1K2 - process.xml 1 E DEPLOYMENT_DISTRIBUTION DISTRIBUTING - #4->#1 P1K2 - DeploymentDistributionRecord {"partitionId":2} 1 E DEPLOYMENT_DISTRIBUTION DISTRIBUTING - #5->#1 P1K2 - DeploymentDistributionRecord {"partitionId":3} 2 C DEPLOYMENT DISTRIBUTE - #2->-1 P1K2 - process.xml 3 C DEPLOYMENT DISTRIBUTE - #2->-1 P1K2 - process.xml 1 C DEPLOYMENT_DISTRIBUTION COMPLETE - #6->-1 P1K2 - DeploymentDistributionRecord {"partitionId":2} 1 E DEPLOYMENT_DISTRIBUTION COMPLETED - #7->#6 P1K2 - DeploymentDistributionRecord {"partitionId":2} 2 E DEPLOYMENT DISTR - #3->#1 P1K2 - process.xml 2 E DEPLOYMENT DISTR - #4->#2 P1K2 - process.xml ``` After this PR, the same log is outputted as: ``` 2 C DPLY DISTRIBUTE - #1->-1 P1K2 - process.xml 3 C DPLY DISTRIBUTE - #1->-1 P1K2 - process.xml 1 C DPLY CREATE - #1->-1 -1 - 1 E PROC CREATED - #2->#1 P1K1 - process.xml -> "shouldR..ecovery" (version:1) 1 E DPLY CREATED - #3->#1 P1K2 - process.xml 1 E DSTR DISTRIBUTING - #4->#1 P1K2 - on partition 2 1 E DSTR DISTRIBUTING - #5->#1 P1K2 - on partition 3 2 C DPLY DISTRIBUTE - #2->-1 P1K2 - process.xml 3 C DPLY DISTRIBUTE - #2->-1 P1K2 - process.xml 1 C DSTR COMPLETE - #6->-1 P1K2 - on partition 2 1 E DSTR COMPLETED - #7->#6 P1K2 - on partition 2 2 E DPLY DISTRIBUTED - #3->#1 P1K2 - process.xml 2 E DPLY DISTRIBUTED - #4->#2 P1K2 - process.xml ``` ## Related issues <!-- Which issues are closed by this PR or are related --> relates to #10064 Co-authored-by: Nico Korthout <nico.korthout@camunda.com>
zeebe-bors-camunda bot
added a commit
that referenced
this issue
Aug 23, 2022
10144: Add more abbreviations to the compact record logger r=saig0 a=korthout ## Description <!-- Please explain the changes you made here. --> While writing an engine test, I encountered some more unabbreviated record value types. This adds a few more abbreviations to create a compact, and easier-to-read record log. ### Before ``` -------- [Partition] ['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 DPLY CREATE - #1-> -1 -1 - E PROC CREATED - #2->#1 K01 - process.xml -> "process" (version:1) E DPLY CREATED - #3->#1 K02 - process.xml E DPLY FULLY_DISTRIBUTED - #4->#1 K02 - C PROC_INST_CREATION CREATE - #5-> -1 -1 - new <process "process"> (default start) with variables: {x=variable} E VAR CREATED - #6->#5 K04 - x->"variable" in <process [K03]> C PROC_INST ACTIVATE - #7->#5 K03 - PROCESS "process" in <process "process"[K03]> E PROC_INST_CREATION CREATED - #8->#5 K05 - new <process "process"> (default start) with variables: {x=variable} E PROC_INST ACTIVATING - #9->#7 K03 - PROCESS "process" in <process "process"[K03]> E PROC_INST ACTIVATED - #10->#7 K03 - PROCESS "process" in <process "process"[K03]> C PROC_INST ACTIVATE - #11->#7 -1 - START_EVENT "startEv..b44a7b4" in <process "process"[K03]> C PROC_INST_MODIFICATION MODIFY - #12-> -1 K03 - ProcessInstanceModificationRecord {"processInstanceKey":2251799813685251,"terminateInstructions":[],"activateInstructions":[{"elementId":"B","ancestorScopeKey":-1,"variableInstructions":[{"elementId":"","variables":{"x":"updated"}}]}]} E PROC_INST ACTIVATING - #13->#11 K06 - START_EVENT "startEv..b44a7b4" in <process "process"[K03]> E PROC_INST ACTIVATED - #14->#11 K06 - START_EVENT "startEv..b44a7b4" in <process "process"[K03]> C PROC_INST COMPLETE - #15->#11 K06 - START_EVENT "startEv..b44a7b4" in <process "process"[K03]> E VAR UPDATED - #16->#12 K04 - x->"updated" in <process [K03]> C PROC_INST ACTIVATE - #17->#12 K07 - USER_TASK "B" in <process "process"[K03]> E PROC_INST_MODIFICATION MODIFIED - #18->#12 K03 - ProcessInstanceModificationRecord {"processInstanceKey":2251799813685251,"terminateInstructions":[],"activateInstructions":[{"elementId":"B","ancestorScopeKey":-1,"variableInstructions":[{"elementId":"","variables":{"x":"updated"}}]}]} E PROC_INST COMPLETING - #19->#15 K06 - START_EVENT "startEv..b44a7b4" in <process "process"[K03]> E PROC_INST COMPLETED - #20->#15 K06 - START_EVENT "startEv..b44a7b4" in <process "process"[K03]> E PROC_INST SEQ_FLOW_TAKEN - #21->#15 K08 - SEQUENCE_FLOW "sequenc..25183c6" in <process "process"[K03]> C PROC_INST ACTIVATE - #22->#15 K09 - USER_TASK "A" in <process "process"[K03]> E PROC_INST ACTIVATING - #23->#17 K07 - USER_TASK "B" in <process "process"[K03]> E JOB CREATED - #24->#17 K10 - K10 "io.camunda.zeebe:userTask" `@"B"[K07]` 1 retries, in <process "process"[K03]> (no vars) E PROC_INST ACTIVATED - #25->#17 K07 - USER_TASK "B" in <process "process"[K03]> E PROC_INST ACTIVATING - #26->#22 K09 - USER_TASK "A" in <process "process"[K03]> E JOB CREATED - #27->#22 K11 - K11 "io.camunda.zeebe:userTask" `@"A"[K09]` 1 retries, in <process "process"[K03]> (no vars) E PROC_INST ACTIVATED - #28->#22 K09 - USER_TASK "A" in <process "process"[K03]> ``` ### After ``` -------- [Partition] ['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 DPLY CREATE - #1-> -1 -1 - E PROC CREATED - #2->#1 K01 - process.xml -> "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"> (default start) with variables: {x=variable} E VAR CREATED - #6->#5 K04 - x->"variable" in <process [K03]> C PI ACTIVATE - #7->#5 K03 - PROCESS "process" in <process "process"[K03]> E CREA CREATED - #8->#5 K05 - new <process "process"> (default start) with variables: {x=variable} E PI ACTIVATING - #9->#7 K03 - PROCESS "process" in <process "process"[K03]> E PI ACTIVATED - #10->#7 K03 - PROCESS "process" in <process "process"[K03]> C PI ACTIVATE - #11->#7 -1 - START_EVENT "startEv..ea8bb20" in <process "process"[K03]> C MOD MODIFY - #12-> -1 K03 - ProcessInstanceModificationRecord {"processInstanceKey":2251799813685251,"terminateInstructions":[],"activateInstructions":[{"elementId":"B","ancestorScopeKey":-1,"variableInstructions":[{"elementId":"","variables":{"x":"updated"}}]}]} E PI ACTIVATING - #13->#11 K06 - START_EVENT "startEv..ea8bb20" in <process "process"[K03]> E PI ACTIVATED - #14->#11 K06 - START_EVENT "startEv..ea8bb20" in <process "process"[K03]> C PI COMPLETE - #15->#11 K06 - START_EVENT "startEv..ea8bb20" in <process "process"[K03]> E VAR UPDATED - #16->#12 K04 - x->"updated" in <process [K03]> C PI ACTIVATE - #17->#12 K07 - USER_TASK "B" in <process "process"[K03]> E MOD MODIFIED - #18->#12 K03 - ProcessInstanceModificationRecord {"processInstanceKey":2251799813685251,"terminateInstructions":[],"activateInstructions":[{"elementId":"B","ancestorScopeKey":-1,"variableInstructions":[{"elementId":"","variables":{"x":"updated"}}]}]} E PI COMPLETING - #19->#15 K06 - START_EVENT "startEv..ea8bb20" in <process "process"[K03]> E PI COMPLETED - #20->#15 K06 - START_EVENT "startEv..ea8bb20" in <process "process"[K03]> E PI SEQ_FLOW_TAKEN - #21->#15 K08 - SEQUENCE_FLOW "sequenc..d3f792d" in <process "process"[K03]> C PI ACTIVATE - #22->#15 K09 - USER_TASK "A" in <process "process"[K03]> E PI ACTIVATING - #23->#17 K07 - USER_TASK "B" in <process "process"[K03]> E JOB CREATED - #24->#17 K10 - K10 "io.camunda.zeebe:userTask" `@"B"[K07]` 1 retries, in <process "process"[K03]> (no vars) E PI ACTIVATED - #25->#17 K07 - USER_TASK "B" in <process "process"[K03]> E PI ACTIVATING - #26->#22 K09 - USER_TASK "A" in <process "process"[K03]> E JOB CREATED - #27->#22 K11 - K11 "io.camunda.zeebe:userTask" `@"A"[K09]` 1 retries, in <process "process"[K03]> (no vars) E PI ACTIVATED - #28->#22 K09 - USER_TASK "A" in <process "process"[K03]> ``` ## Related issues <!-- Which issues are closed by this PR or are related --> while working on #9663 Co-authored-by: Nico Korthout <nico.korthout@camunda.com>
korthout
added a commit
that referenced
this issue
Aug 23, 2022
The compact record logger abbreviates long rejection reasons. This makes sense, because these can be excessively long in some cases. However, the compact record logger shouldn't reduce the usefulness of this data. Take for example the following compacted record log: ``` -------- C DPLY CREATE - #1->-1 -1 - R DPLY CREATE - #2->#1 -1 - !INVALID_ARGUMENT (Expected to deploy new resources, but encountered the following errors: 'process.xml': - Element: message_8722b478-fc0f-4c67-82fe-46ee7c067da2 > extensionElements > subscription - ERROR: Expecte..) -------------- Deployed Processes ---------------------- ``` Is it clear what the problem is and what the user did wrong? Well, this happened to me while writing a test and I didn't know what I'd done wrong. This commit allows for a little bit more breathing room to show the rejection reason, while still abbreviating very long rejections. The magic number 500 is hand-picked for no particular reason. ``` -------- C DPLY CREATE - #1->-1 -1 - R DPLY CREATE - #2->#1 -1 - !INVALID_ARGUMENT (Expected to deploy new resources, but encountered the following errors: 'process.xml': - Element: message_252ebafa-ed9a-40a6-be98-ec31e71316a8 > extensionElements > subscription - ERROR: Expected expression but found static value 'key'. An expression must start with '=' (e.g. '=key'). ) -------------- Deployed Processes ---------------------- ``` Now, it's completely clear what my mistake was. I tried to use a static value as correlation key, but it must be an expression. ¯\_(ツ)_/¯ We could consider further abbreviating this rejection message in a smart way, but for now this seems enough.
korthout
added a commit
that referenced
this issue
Aug 23, 2022
The compact record logger abbreviates long rejection reasons. This makes sense, because these can be excessively long in some cases. However, the compact record logger shouldn't reduce the usefulness of this data. Take for example the following compacted record log: ``` -------- C DPLY CREATE - #1->-1 -1 - R DPLY CREATE - #2->#1 -1 - !INVALID_ARGUMENT (Expected to deploy new resources, but encountered the following errors: 'process.xml': - Element: message_8722b478-fc0f-4c67-82fe-46ee7c067da2 > extensionElements > subscription - ERROR: Expecte..) -------------- Deployed Processes ---------------------- ``` Is it clear what the problem is and what the user did wrong? Well, this happened to me while writing a test and I didn't know what I'd done wrong. This commit allows for a little bit more breathing room to show the rejection reason, while still abbreviating very long rejections. The magic number 500 is hand-picked for no particular reason. ``` -------- C DPLY CREATE - #1->-1 -1 - R DPLY CREATE - #2->#1 -1 - !INVALID_ARGUMENT (Expected to deploy new resources, but encountered the following errors: 'process.xml': - Element: message_252ebafa-ed9a-40a6-be98-ec31e71316a8 > extensionElements > subscription - ERROR: Expected expression but found static value 'key'. An expression must start with '=' (e.g. '=key'). ) -------------- Deployed Processes ---------------------- ``` Now, it's completely clear what my mistake was. I tried to use a static value as correlation key, but it must be an expression. ¯\_(ツ)_/¯ We could consider further abbreviating this rejection message in a smart way, but for now this seems enough.
zeebe-bors-camunda bot
added a commit
that referenced
this issue
Aug 24, 2022
10156: Don't over abbreviate rejections in compact record logger r=saig0 a=korthout ## Description <!-- Please explain the changes you made here. --> The compact record logger abbreviates long rejection reasons. This makes sense, because these can be excessively long in some cases. However, the compact record logger shouldn't reduce the usefulness of this data. Before: ``` -------- C DPLY CREATE - #1->-1 -1 - R DPLY CREATE - #2->#1 -1 - !INVALID_ARGUMENT (Expected to deploy new resources, but encountered the following errors: 'process.xml': - Element: message_8722b478-fc0f-4c67-82fe-46ee7c067da2 > extensionElements > subscription - ERROR: Expecte..) -------------- Deployed Processes ---------------------- ``` After: ``` -------- C DPLY CREATE - #1->-1 -1 - R DPLY CREATE - #2->#1 -1 - !INVALID_ARGUMENT (Expected to deploy new resources, but encountered the following errors: 'process.xml': - Element: message_252ebafa-ed9a-40a6-be98-ec31e71316a8 > extensionElements > subscription - ERROR: Expected expression but found static value 'key'. An expression must start with '=' (e.g. '=key'). ) -------------- Deployed Processes ---------------------- ``` We could consider further abbreviating this rejection message in a smart way, but for now this seems enough. ## Related issues <!-- Which issues are closed by this PR or are related --> NA Co-authored-by: Nico Korthout <nico.korthout@camunda.com>
github-actions bot
pushed a commit
that referenced
this issue
Aug 24, 2022
The compact record logger abbreviates long rejection reasons. This makes sense, because these can be excessively long in some cases. However, the compact record logger shouldn't reduce the usefulness of this data. Take for example the following compacted record log: ``` -------- C DPLY CREATE - #1->-1 -1 - R DPLY CREATE - #2->#1 -1 - !INVALID_ARGUMENT (Expected to deploy new resources, but encountered the following errors: 'process.xml': - Element: message_8722b478-fc0f-4c67-82fe-46ee7c067da2 > extensionElements > subscription - ERROR: Expecte..) -------------- Deployed Processes ---------------------- ``` Is it clear what the problem is and what the user did wrong? Well, this happened to me while writing a test and I didn't know what I'd done wrong. This commit allows for a little bit more breathing room to show the rejection reason, while still abbreviating very long rejections. The magic number 500 is hand-picked for no particular reason. ``` -------- C DPLY CREATE - #1->-1 -1 - R DPLY CREATE - #2->#1 -1 - !INVALID_ARGUMENT (Expected to deploy new resources, but encountered the following errors: 'process.xml': - Element: message_252ebafa-ed9a-40a6-be98-ec31e71316a8 > extensionElements > subscription - ERROR: Expected expression but found static value 'key'. An expression must start with '=' (e.g. '=key'). ) -------------- Deployed Processes ---------------------- ``` Now, it's completely clear what my mistake was. I tried to use a static value as correlation key, but it must be an expression. ¯\_(ツ)_/¯ We could consider further abbreviating this rejection message in a smart way, but for now this seems enough. (cherry picked from commit 530bdb0)
github-actions bot
pushed a commit
that referenced
this issue
Aug 24, 2022
The compact record logger abbreviates long rejection reasons. This makes sense, because these can be excessively long in some cases. However, the compact record logger shouldn't reduce the usefulness of this data. Take for example the following compacted record log: ``` -------- C DPLY CREATE - #1->-1 -1 - R DPLY CREATE - #2->#1 -1 - !INVALID_ARGUMENT (Expected to deploy new resources, but encountered the following errors: 'process.xml': - Element: message_8722b478-fc0f-4c67-82fe-46ee7c067da2 > extensionElements > subscription - ERROR: Expecte..) -------------- Deployed Processes ---------------------- ``` Is it clear what the problem is and what the user did wrong? Well, this happened to me while writing a test and I didn't know what I'd done wrong. This commit allows for a little bit more breathing room to show the rejection reason, while still abbreviating very long rejections. The magic number 500 is hand-picked for no particular reason. ``` -------- C DPLY CREATE - #1->-1 -1 - R DPLY CREATE - #2->#1 -1 - !INVALID_ARGUMENT (Expected to deploy new resources, but encountered the following errors: 'process.xml': - Element: message_252ebafa-ed9a-40a6-be98-ec31e71316a8 > extensionElements > subscription - ERROR: Expected expression but found static value 'key'. An expression must start with '=' (e.g. '=key'). ) -------------- Deployed Processes ---------------------- ``` Now, it's completely clear what my mistake was. I tried to use a static value as correlation key, but it must be an expression. ¯\_(ツ)_/¯ We could consider further abbreviating this rejection message in a smart way, but for now this seems enough. (cherry picked from commit 530bdb0)
zeebe-bors-camunda bot
added a commit
that referenced
this issue
Aug 24, 2022
10170: Print record timestamp in compact record logger r=korthout a=korthout ## Description <!-- Please explain the changes you made here. --> When troubleshooting issues (or writing tests) for Timer related topics, we're often interested in both the Timer record's Duedate, as well as the actual time that the record was written, i.e. the record's Timestamp. This PR adds the Timestamp to the compact record logger when there are Timer records on the recorded log. While working on this, I also noticed that the compact record logger's Legend could be improved to only include Partition related info when the partition is actually printed as well (i.e. when there are multiple partitions). This is another PR in a series of QoL improvements I've recently made to the compact record logger. - #10156 - #10144 - #9885 ### Before ``` -------- [Partition] ['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 DPLY CREATE - #1->-1 -1 - E PROC CREATED - #2->#1 K1 - process.xml -> "process" (version:1) E TIME CREATED - #3->#1 K3 - `@"start_1"[-1]` in <process "K1"[?]> due T15:10:34.329 E DPLY CREATED - #4->#1 K2 - process.xml E DPLY FULLY_DISTRIBUTED - #5->#1 K2 - ``` ### After With Timer records: ``` -------- [Timestamp] ['C'ommand/'E'event/'R'ejection] [valueType] [intent] - #[position]->#[source record position] 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' -------- 15:28:01 C DPLY CREATE - #1->-1 -1 - 15:28:02 E PROC CREATED - #2->#1 K1 - process.xml -> "process" (version:1) 15:28:02 E TIME CREATED - #3->#1 K3 - `@"start_1"[-1]` in <process "K1"[?]> due T15:28:03.087 15:28:02 E DPLY CREATED - #4->#1 K2 - process.xml 15:28:02 E DPLY FULLY_DISTRIBUTED - #5->#1 K2 - ``` Without Timer records: ``` -------- ['C'ommand/'E'event/'R'ejection] [valueType] [intent] - #[position]->#[source record position] 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 DPLY CREATE - #1-> -1 -1 - E PROC CREATED - #2->#1 K01 - process.xml -> "process" (version:1) E DPLY CREATED - #3->#1 K02 - process.xml E DPLY FULLY_DISTRIBUTED - #4->#1 K02 - ``` When there are multiple partitions: ``` -------- [Partition] ['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' -------- 1 C DPLY CREATE - #1->-1 -1 - 1 E PROC CREATED - #2->#1 P1K1 - process.bpmn -> "shouldR..ecovery" (version:1) 1 E DPLY CREATED - #3->#1 P1K2 - process.bpmn 1 E DSTR DISTRIBUTING - #4->#1 P1K2 - on partition 2 1 E DSTR DISTRIBUTING - #5->#1 P1K2 - on partition 3 1 C DSTR COMPLETE - #6->-1 P1K2 - on partition 2 1 C DSTR COMPLETE - #7->-1 P1K2 - on partition 3 1 E DSTR COMPLETED - #8->#6 P1K2 - on partition 2 1 E DSTR COMPLETED - #9->#7 P1K2 - on partition 3 1 E DPLY FULLY_DISTRIBUTED - #10->#7 P1K2 - 2 C DPLY DISTRIBUTE - #1->-1 P1K2 - process.bpmn 2 E DPLY DISTRIBUTED - #2->#1 P1K2 - process.bpmn 3 C DPLY DISTRIBUTE - #1->-1 P1K2 - process.bpmn 3 E DPLY DISTRIBUTED - #2->#1 P1K2 - process.bpmn ``` ## Related issues <!-- Which issues are closed by this PR or are related --> relates to #10169 Co-authored-by: Nico Korthout <nico.korthout@camunda.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
The text was updated successfully, but these errors were encountered: