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

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

Merged

Conversation

KarlK90
Copy link
Member

@KarlK90 KarlK90 commented May 7, 2022

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

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).

@github-actions github-actions bot added the core label May 7, 2022
@KarlK90 KarlK90 requested a review from a team May 7, 2022 19:24
@KarlK90 KarlK90 force-pushed the feature/unit-tests-reset-timer-timestamp-logging branch 2 times, most recently from 3f65739 to 1b25ffc Compare May 7, 2022 19:30
@KarlK90
Copy link
Member Author

KarlK90 commented May 7, 2022

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

@precondition
Copy link
Contributor

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 KarlK90 force-pushed the feature/unit-tests-reset-timer-timestamp-logging branch from 1b25ffc to 475a2c9 Compare May 8, 2022 13:22
@KarlK90 KarlK90 force-pushed the feature/unit-tests-reset-timer-timestamp-logging branch from fabf77e to 66a73fc Compare May 8, 2022 16:17
@KarlK90
Copy link
Member Author

KarlK90 commented May 8, 2022

@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.

@KarlK90 KarlK90 force-pushed the feature/unit-tests-reset-timer-timestamp-logging branch 3 times, most recently from 5b9f7b6 to 7e4d888 Compare May 8, 2022 21:03
tests/test_common/test_keymap_key.cpp Outdated Show resolved Hide resolved
tests/test_common/test_keymap_key.cpp Outdated Show resolved Hide resolved
tests/test_common/test_keymap_key.cpp Outdated Show resolved Hide resolved
@joukewitteveen
Copy link
Contributor

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.

Copy link
Member

@drashna drashna left a comment

Choose a reason for hiding this comment

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

__attribute__((weak))

Copy link
Contributor

@joukewitteveen joukewitteveen left a comment

Choose a reason for hiding this comment

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

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

@KarlK90 KarlK90 force-pushed the feature/unit-tests-reset-timer-timestamp-logging branch 4 times, most recently from 8d84a65 to fb21c93 Compare July 2, 2022 16:36
@KarlK90 KarlK90 force-pushed the feature/unit-tests-reset-timer-timestamp-logging branch 5 times, most recently from 44640ac to 6b8d1b6 Compare August 18, 2022 11:36
@joukewitteveen
Copy link
Contributor

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.

@KarlK90 KarlK90 force-pushed the feature/unit-tests-reset-timer-timestamp-logging branch from 6b8d1b6 to 07bccf0 Compare September 13, 2022 13:42
@github-actions
Copy link

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.

@github-actions github-actions bot added the stale Issues or pull requests that have become inactive without resolution. label Oct 29, 2022
@KarlK90
Copy link
Member Author

KarlK90 commented Nov 8, 2022

On hold until DD keycodes have been merged

@sigprof
Copy link
Contributor

sigprof commented Nov 8, 2022

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

@github-actions github-actions bot removed the stale Issues or pull requests that have become inactive without resolution. label Nov 9, 2022
@KarlK90
Copy link
Member Author

KarlK90 commented Nov 17, 2022

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 KarlK90 force-pushed the feature/unit-tests-reset-timer-timestamp-logging branch from 07bccf0 to 878fc32 Compare December 5, 2022 19:41
@github-actions github-actions bot added cli qmk cli command python labels Dec 5, 2022
quantum/quantum_keycodes.h Outdated Show resolved Hide resolved
@KarlK90 KarlK90 marked this pull request as draft December 6, 2022 08:49
@KarlK90 KarlK90 force-pushed the feature/unit-tests-reset-timer-timestamp-logging branch 3 times, most recently from 6d1e585 to c44c3a3 Compare December 11, 2022 14:09
@KarlK90 KarlK90 marked this pull request as ready for review December 11, 2022 14:10
@KarlK90 KarlK90 requested review from a team and zvecr December 11, 2022 14:11
@KarlK90
Copy link
Member Author

KarlK90 commented Dec 11, 2022

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

@KarlK90 KarlK90 force-pushed the feature/unit-tests-reset-timer-timestamp-logging branch from c44c3a3 to 838ae83 Compare December 12, 2022 21:17
@KarlK90 KarlK90 force-pushed the feature/unit-tests-reset-timer-timestamp-logging branch from 838ae83 to 1ec9505 Compare December 14, 2022 10:04
@tzarc tzarc merged commit 962e4c0 into qmk:develop Dec 14, 2022
omikronik pushed a commit to omikronik/qmk_firmware that referenced this pull request Jan 22, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
cli qmk cli command core python
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants