[Test] Reset timer for every unit test and provide timestamps for log messages

[KarlK90]

Description

Previously the unit-tests where run with a continuously running timer, which can trigger timing bugs in unrelated unit tests. To remedy this we now reset the timer for each unit test. All events in log messages now also contain a timestamp and key events show how long they have been held/released. This is meant as a convenience feature for debugging and developing unit-tests.

e.g. the quite complex ANewTapWithinTappingTermIsBuggy test on failure before:

Tapping.ANewTapWithinTappingTermIsBuggy failed!
[ TRACE    ] Key pressed:  (7,0)
[ TRACE    ] Key released: (7,0)
[ TRACE    ] Keyboard Report: Mods (0) Keys (19)
[ TRACE    ] Keyboard Report: Mods (0) Keys ()
[ TRACE    ] Key pressed:  (7,0)
[ TRACE    ] Keyboard Report: Mods (0) Keys (19)
[ TRACE    ] Key released: (7,0)
[ TRACE    ] Keyboard Report: Mods (0) Keys ()
[ TRACE    ] Key pressed:  (7,0)
[ TRACE    ] Key released: (7,0)
[ TRACE    ] Keyboard Report: Mods (0) Keys (19)
[ TRACE    ] Keyboard Report: Mods (0) Keys ()
[ TRACE    ] Key pressed:  (7,0)
[ TRACE    ] Key released: (7,0)
[ TRACE    ] Keyboard Report: Mods (2) Keys ()
[ TRACE    ] Keyboard Report: Mods (0) Keys ()
[ TRACE    ] Keyboard Report: Mods (0) Keys (19)
[ TRACE    ] Keyboard Report: Mods (0) Keys ()
[ INFO     ] TestFixture clean-up start.
[ INFO     ] TestFixture clean-up end.

and with these changes:

Tapping.ANewTapWithinTappingTermIsBuggy failed!
[ LEVEL    ] [TIME] [EVENT]
[ INFO     ] 0      tapping term is 200ms
[ TRACE    ] 0      pressed:  MT(MOD_LSFT, KC_P)
[ TRACE    ] 0      1 keyboard task loop
[ TRACE    ] 1      released: MT(MOD_LSFT, KC_P) was pressed for 1ms
[ TRACE    ] 1      1 keyboard task loop
[ TRACE    ] 1      report:   (KC_P) []
[ TRACE    ] 1      report:   empty
[ TRACE    ] 2      pressed:  MT(MOD_LSFT, KC_P)
[ TRACE    ] 2      1 keyboard task loop
[ TRACE    ] 2      report:   (KC_P) []
[ TRACE    ] 3      released: MT(MOD_LSFT, KC_P) was pressed for 1ms
[ TRACE    ] 3      201 keyboard task loops
[ TRACE    ] 3      report:   empty
[ TRACE    ] 204    pressed:  MT(MOD_LSFT, KC_P)
[ TRACE    ] 204    1 keyboard task loop
[ TRACE    ] 205    released: MT(MOD_LSFT, KC_P) was pressed for 1ms
[ TRACE    ] 205    201 keyboard task loops
[ TRACE    ] 205    report:   (KC_P) []
[ TRACE    ] 205    report:   empty
[ TRACE    ] 406    pressed:  MT(MOD_LSFT, KC_P)
[ TRACE    ] 406    200 keyboard task loops
[ TRACE    ] 606    released: MT(MOD_LSFT, KC_P) was pressed for 200ms
[ TRACE    ] 606    1 keyboard task loop
[ TRACE    ] 606    report:   () [KC_LEFT_SHIFT]
[ TRACE    ] 606    report:   empty
[ INFO     ] 607    test fixture clean-up start.
[ TRACE    ] 607    2000 keyboard task loops
[ TRACE    ] 2607   2000 keyboard task loops
[ INFO     ] 4607   test fixture clean-up end.

Types of Changes

• Core
• Bugfix
• New feature
• Enhancement/optimization
• Keyboard (addition or update)
• Keymap/layout/userspace (addition or update)
• Documentation

Issues Fixed or Closed by This PR

• Cherry-picked from [Core] Refactor keyevent_t for 1ms timing resolution  #15847 which will be WIP for longer time.

Checklist

• My code follows the code style of this project: C, Python
• I have read the PR Checklist document and have made the appropriate changes.
• My change requires a change to the documentation.
• I have updated the documentation accordingly.
• I have read the CONTRIBUTING document.
• I have added tests to cover my changes.
• I have tested the changes and verified that they work and don't break anything (as well as I can manage).

[KarlK90]

CC: @filterpaper @precondition @joukewitteveen as you are involved with unit tests recently and might this feature useful?

[precondition]

I'd add an explanation of what the numbers after [TRACE] mean in the docs page on unit tests. It's not obvious that it is a timestamp.

[KarlK90]

@precondition I did go a bit further and included a header for the output that explains each column.

For better introspection I prototyped a mechanism that resolves the usb report keys and mods to readable constants, furthermore the QMK keycode for each button is now stored in the keycode on construction (although with a bit ugly C stringify magic). I updated the log output in the description of this PR accordingly.

[joukewitteveen]

CC: @filterpaper @precondition @joukewitteveen as you are involved with unit tests recently and might this feature useful?

I did not test the code in this PR and the changes in #16394 would be affected by the changes in this PR: the KEYMAP_KEY macro is not yet used in #16394.

In case of failing tests related to tap dance, I can see how it can be pleasant to restart the timer for each test. That would keep the numbers down a bit.

[drashna]

__attribute__((weak)) ✅

[joukewitteveen]

The tap dance tests added with #16394 should also be updated to use the KEYMAP_KEY macro.

[joukewitteveen]

The tap dance tests added with #16394 should also be updated to use the KEYMAP_KEY macro.

Note that these updates of the tap dance tests are still missing from this PR.

[github-actions]

Thank you for your contribution!
This pull request has been automatically marked as stale because it has not had activity in the last 45 days. It will be closed in 30 days if no further activity occurs. Please feel free to give a status update now, or re-open when it's ready.
For maintainers: Please label with bug, awaiting review, breaking_change, in progress, or on hold to prevent the issue from being re-flagged.

[KarlK90]

On hold until DD keycodes have been merged

[sigprof]

But #18643 had been merged… or do you mean something else?

[KarlK90]

But #18643 had been merged… or do you mean something else?

You are right, I missed that. I'll generate the keycode lookup table from the keycode specifications.

[KarlK90]

Converted the keycode lookup table to be generated from keycode definitions and extended the unit-tests. This is now ready for review.