The lifecyclePhase in ActorTask is not volatile #999
Assignees
Labels
version:1.3.14
Marks an issue as being completely or in parts released in 1.3.14
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
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>
This was referenced Aug 23, 2022
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>
This was referenced Aug 24, 2022
saig0
added
release/8.0.8
version:1.3.14
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
We should validate if this is a real problem. See for example
ActorTask#tryWait, where it is checked and another thread could have waken up the task already again (is this flag written concurrently?).The text was updated successfully, but these errors were encountered: