Print record timestamp in compact record logger #10170

korthout · 2022-08-24T13:46:52Z

Description

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.

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            - #01-> -1  -1 - 
E PROC CREATED           - #02->#01 K01 - process.xml -> "process" (version:1)
E DPLY CREATED           - #03->#01 K02 - process.xml
E DPLY FULLY_DISTRIBUTED - #04->#01 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

relates to #10169

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.

When troubleshooting issues or writing tests for Timer related topics, we're often not only interested in the Duedate of the timer, but also in the Timestamp of the records. Since these timestamps are generally irrelevant for other types of tests, it makes sense to only log them when there are Timer records present. As a format I've chosen a small but simple form (HH:mm:ss). If needed we could investigate more advanced formatting in the future. E.g. a format that only shows the least amount of data: only seconds if those matter, or include hours if those matter. For now, this short form in combination with hiding it when its not useful seems useful and easy to build. Timestamps are naturally found at the start of log lines, so I've chosen to prefix each record summary with it.

If there are timer events, the compact record logger's Legend should contain [Timestamp], so readers understand the summary. But, the Timestamp isn't always part of the compact log. In that case, the [Timestamp] should also be removed from the Legend.

If there are multiple partitions, the compact record logger's Legend should contain [Partition] and each key will contain a [Pn] prefix, so readers understand the summary. But, there aren't always multiple partitions, and then the partition isn't part of the compact log. In that case, the [Partition] should also be removed from the Legend. I've also split up the Legend construction a bit further, to keep it somewhat readable.

github-actions · 2022-08-24T14:04:16Z

Test Results

  853 files +  1   853 suites +1 1h 35m 7s ⏱️ - 9m 6s
6 612 tests +28 6 600 ✔️ +27 11 💤 ±0 1 ❌ +1
6 796 runs +28 6 784 ✔️ +27 11 💤 ±0 1 ❌ +1

For more details on these failures, see this check.

Results for commit 42936ee. ± Comparison against base commit ec06278.

♻️ This comment has been updated with latest results.

remcowesterhoud

I like the changes 🏆 Nothing to add LGTM

korthout · 2022-08-24T14:24:13Z

bors merge

zeebe-bors-camunda · 2022-08-24T14:56:09Z

Build succeeded:

backport-action · 2022-08-24T14:57:23Z

Successfully created backport PR #10175 for stable/1.3.

backport-action · 2022-08-24T14:57:32Z

Successfully created backport PR #10176 for stable/8.0.

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>

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>

korthout added 3 commits August 24, 2022 15:12

korthout requested a review from remcowesterhoud August 24, 2022 13:50

korthout marked this pull request as ready for review August 24, 2022 13:50

korthout added backport stable/1.3 labels Aug 24, 2022

korthout self-assigned this Aug 24, 2022

remcowesterhoud approved these changes Aug 24, 2022

View reviewed changes

zeebe-bors-camunda bot merged commit 1d90955 into main Aug 24, 2022

zeebe-bors-camunda bot deleted the korthout-timestamp-in-compact-record-log branch August 24, 2022 14:56

backport-action mentioned this pull request Aug 24, 2022

[Backport stable/1.3] Print record timestamp in compact record logger #10175

Merged

backport-action mentioned this pull request Aug 24, 2022

[Backport stable/8.0] Print record timestamp in compact record logger #10176

Merged

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

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Print record timestamp in compact record logger #10170

Print record timestamp in compact record logger #10170

korthout commented Aug 24, 2022 •

edited

github-actions bot commented Aug 24, 2022 •

edited

remcowesterhoud left a comment

korthout commented Aug 24, 2022

zeebe-bors-camunda bot commented Aug 24, 2022

backport-action commented Aug 24, 2022

backport-action commented Aug 24, 2022

Print record timestamp in compact record logger #10170

Print record timestamp in compact record logger #10170

Conversation

korthout commented Aug 24, 2022 • edited

Description

Before

After

Related issues

Definition of Done

github-actions bot commented Aug 24, 2022 • edited

Test Results

remcowesterhoud left a comment

Choose a reason for hiding this comment

korthout commented Aug 24, 2022

zeebe-bors-camunda bot commented Aug 24, 2022

backport-action commented Aug 24, 2022

backport-action commented Aug 24, 2022

korthout commented Aug 24, 2022 •

edited

github-actions bot commented Aug 24, 2022 •

edited