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

Don't over abbreviate rejections in compact record logger #10156

Merged
merged 1 commit into from
Aug 24, 2022

Conversation

korthout
Copy link
Member

@korthout korthout commented Aug 23, 2022

Description

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

NA

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 the fix to the last two minor versions. You can trigger a backport by assigning labels (e.g. backport stable/1.3) 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
  • If the PR changes how BPMN processes are validated (e.g. support new BPMN element) then the Camunda modeling team should be informed to adjust the BPMN linting.

Please refer to our review guidelines.

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 korthout force-pushed the korthout-rejection-abbreviation branch from 4fd2c4e to 530bdb0 Compare August 23, 2022 15:05
@korthout korthout marked this pull request as ready for review August 23, 2022 15:07
@korthout korthout changed the title Abbreviate rejections slightly less in compact record logger Don't over abbreviate rejections in compact record logger Aug 23, 2022
@korthout korthout requested a review from saig0 August 23, 2022 15:08
@korthout korthout self-assigned this Aug 23, 2022
@github-actions
Copy link
Contributor

Test Results

   851 files  ±    0     851 suites  ±0   1h 37m 46s ⏱️ - 6m 12s
6 423 tests  - 160  6 412 ✔️  - 160  11 💤 ±0  0 ±0 
6 607 runs   - 160  6 596 ✔️  - 160  11 💤 ±0  0 ±0 

Results for commit 530bdb0. ± Comparison against base commit 791c8cf.

Copy link
Member

@saig0 saig0 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@korthout great commit message 👍

@saig0
Copy link
Member

saig0 commented Aug 24, 2022

bors merge

@zeebe-bors-camunda
Copy link
Contributor

Build succeeded:

@zeebe-bors-camunda zeebe-bors-camunda bot merged commit ac67c70 into main Aug 24, 2022
@zeebe-bors-camunda zeebe-bors-camunda bot deleted the korthout-rejection-abbreviation branch August 24, 2022 03:49
@backport-action
Copy link
Collaborator

Successfully created backport PR #10157 for stable/1.3.

@backport-action
Copy link
Collaborator

Successfully created backport PR #10158 for stable/8.0.

zeebe-bors-camunda bot added a commit that referenced this pull request Aug 24, 2022
10157: [Backport stable/1.3] Don't over abbreviate rejections in compact record logger r=korthout a=backport-action

# Description
Backport of #10156 to `stable/1.3`.

relates to 

Co-authored-by: Nico Korthout <nico.korthout@camunda.com>
zeebe-bors-camunda bot added a commit that referenced this pull request Aug 24, 2022
10158: [Backport stable/8.0] Don't over abbreviate rejections in compact record logger r=korthout a=backport-action

# Description
Backport of #10156 to `stable/8.0`.

relates to 

Co-authored-by: Nico Korthout <nico.korthout@camunda.com>
zeebe-bors-camunda bot added a commit that referenced this pull request 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 pull request Aug 24, 2022
10176: [Backport stable/8.0] Print record timestamp in compact record logger r=korthout a=backport-action

# Description
Backport of #10170 to `stable/8.0`.

relates to #10156 #10144 #9885 #10169

Co-authored-by: Nico Korthout <nico.korthout@camunda.com>
zeebe-bors-camunda bot added a commit that referenced this pull request Aug 24, 2022
10175: [Backport stable/1.3] Print record timestamp in compact record logger r=korthout a=backport-action

# Description
Backport of #10170 to `stable/1.3`.

relates to #10156 #10144 #9885 #10169

Co-authored-by: Nico Korthout <nico.korthout@camunda.com>
@saig0 saig0 added release/8.0.8 version:1.3.14 Marks an issue as being completely or in parts released in 1.3.14 labels Sep 1, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
version:1.3.14 Marks an issue as being completely or in parts released in 1.3.14
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants