Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

No updates for dirty keys #32

Closed
meyerdan opened this issue Jul 19, 2016 · 2 comments
Closed

No updates for dirty keys #32

meyerdan opened this issue Jul 19, 2016 · 2 comments
Assignees

Comments

@meyerdan
Copy link
Member

meyerdan commented Jul 19, 2016

When an update for a particular key is scheduled via the log work buffer, no further updates can be accepted for that key until this update either succeeded or failed.

Notes:

  • The update "succeeded" means that a) the log entry has been written and b) the corresponding indices have been updated.
  • The pipeline needs to "stall" until the update has been processed downstream
@meyerdan meyerdan added the ready label Jul 19, 2016
@ThorbenLindhauer ThorbenLindhauer self-assigned this Jul 25, 2016
ThorbenLindhauer added a commit that referenced this issue Aug 3, 2016
- although we follow the single writer principle, due to batching
  reqeuests are not processed sequentially from reception to response
- in consequence, requests may be received that work with the same
  resource, for example two task completion requests
- this commit ensures that indexes and logs are consistent, even when
  new log entries have been submitted to the log write buffer but not have
  not yet been committed
- in this case, the index keys that are going to be change based on the
  new log entry are marked as dirty
- requests that require access to dirty index keys are postponed
- while a request is postponed, no other request is handled; instead,
  handling the request is constantly retried; eventually, the dirty index
  keys are resolved and the request can be completed

related to #32
@ThorbenLindhauer
Copy link
Member

Remaining discussion points:

  • When using a dispatcher in pipeline mode, the order of subscriptions is relevant. When we bootstrap the broker, we have subscriptions forthe log appender, request workers and index writers. The order is implicit in the code and could change without notice when we refactor something. I'd like to have that clear in one place.
  • I did not yet add the isMarkedFailed flag to the BlockHandler interface, such that block handlers always receive blocks where all entries are marked as failed or not. I postponed this since we don't need it yet and I wanted to get this issue done.
  • I don't really like the changes I made to the log (https://github.com/camunda-tngp/log/commit/2d2fefcbe5251c01e7952806c0be98582181c976). Perhaps there is a better solution.

@ThorbenLindhauer
Copy link
Member

Discussion regarding point 1:

When creating a dispatcher, it must be possible to statically define subscription stages. Stages are in order, i.e. all subscriptions of a certain stage are notified before all subscriptions of the following stage. When a subscription is created, a stage must be chosen. This way, the order of subscriptions is made explicit.

bors bot added a commit that referenced this issue Sep 6, 2018
1275: build(deps): bump appassembler-maven-plugin from 1.10 to 2.0.0 r=menski a=dependabot[bot]

Bumps [appassembler-maven-plugin](https://github.com/mojohaus/appassembler) from 1.10 to 2.0.0.
<details>
<summary>Commits</summary>

- [`1ec8420`](mojohaus/appassembler@1ec8420) [maven-release-plugin] prepare release appassembler-2.0.0
- [`8eb2fec`](mojohaus/appassembler@8eb2fec) revert back to mojo-parent-39 to get good build again.
- [`e098be8`](mojohaus/appassembler@e098be8) Fixed appveyor.yml using Maven 3.2.5 to
- [`ed174bb`](mojohaus/appassembler@ed174bb) Fixed [#43](https://github-redirect.dependabot.com/mojohaus/appassembler/issues/43)
- [`fff8d9f`](mojohaus/appassembler@fff8d9f) Based on Maven 3.3.X we can only use JDK 7 and JDK 8
- [`264c1a5`](mojohaus/appassembler@264c1a5) Added appveyor build on windows.
- [`64ebaa6`](mojohaus/appassembler@64ebaa6) Fixed [#40](https://github-redirect.dependabot.com/mojohaus/appassembler/issues/40)
- [`b70ba04`](mojohaus/appassembler@b70ba04) Fixed [#32](https://github-redirect.dependabot.com/mojohaus/appassembler/issues/32)
- [`b3c3bcd`](mojohaus/appassembler@b3c3bcd) Fixed [#29](https://github-redirect.dependabot.com/mojohaus/appassembler/issues/29)
- [`e99ba84`](mojohaus/appassembler@e99ba84) Fixed [#35](https://github-redirect.dependabot.com/mojohaus/appassembler/issues/35)
- Additional commits viewable in [compare view](mojohaus/appassembler@appassembler-1.10...appassembler-2.0.0)
</details>
<br />

[![Dependabot compatibility score](https://api.dependabot.com/badges/compatibility_score?dependency-name=org.codehaus.mojo:appassembler-maven-plugin&package-manager=maven&previous-version=1.10&new-version=2.0.0)](https://dependabot.com/compatibility-score.html?dependency-name=org.codehaus.mojo:appassembler-maven-plugin&package-manager=maven&previous-version=1.10&new-version=2.0.0)

Dependabot will resolve any conflicts with this PR as long as you don't alter it yourself. You can also trigger a rebase manually by commenting `@dependabot rebase`.

---

**Note:** This repo was added to Dependabot recently, so you'll receive a maximum of 5 PRs for your first few update runs. Once an update run creates fewer than 5 PRs we'll remove that limit.

You can always request more updates by clicking `Bump now` in your [Dependabot dashboard](https://app.dependabot.com).

<details>
<summary>Dependabot commands and options</summary>
<br />

You can trigger Dependabot actions by commenting on this PR:
- `@dependabot rebase` will rebase this PR
- `@dependabot merge` will merge this PR after your CI passes on it
- `@dependabot cancel merge` will cancel a previously requested merge
- `@dependabot reopen` will reopen this PR if it is closed
- `@dependabot ignore this [patch|minor|major] version` will close this PR and stop Dependabot creating any more for this minor/major version (unless you reopen the PR or upgrade to it yourself)
- `@dependabot ignore this dependency` will close this PR and stop Dependabot creating any more for this dependency (unless you reopen the PR or upgrade to it yourself)
- `@dependabot use these labels` will set the current labels as the default for future PRs for this repo and language
- `@dependabot use these reviewers` will set the current reviewers as the default for future PRs for this repo and language
- `@dependabot use these assignees` will set the current assignees as the default for future PRs for this repo and language
- `@dependabot use this milestone` will set the current milestone as the default for future PRs for this repo and language
- `@dependabot badge me` will comment on this PR with code to add a "Dependabot enabled" badge to your readme

Additionally, you can set the following in your Dependabot [dashboard](https://app.dependabot.com):
- Update frequency (including time of day and day of week)
- Automerge options (never/patch/minor, and dev/runtime dependencies)
- Pull request limits (per update run and/or open at any time)
- Out-of-range updates (receive only lockfile updates, if desired)
- Security updates (receive only security updates, if desired)

Finally, you can contact us by mentioning @dependabot.

</details>

Co-authored-by: dependabot[bot] <support@dependabot.com>
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>
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
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants