Add timestamps to test fixture logging events and reset timer for eac…

…h test

platforms/test/timer.c

@@ -15,8 +15,9 @@
  */
 
 #include "timer.h"
+#include <stdatomic.h>
 
-static uint32_t current_time = 0;
+static atomic_uint_least32_t current_time = 0;
 
 void timer_init(void) { current_time = 0; }
 

tests/test_common/matrix.c

@@ -38,9 +38,11 @@ void matrix_init_kb(void) {}
 
 void matrix_scan_kb(void) {}
 
-void press_key(uint8_t col, uint8_t row) { matrix[row] |= 1 << col; }
+void press_key(uint8_t col, uint8_t row) { matrix[row] |= (matrix_row_t)1 << col; }
 
-void release_key(uint8_t col, uint8_t row) { matrix[row] &= ~(1 << col); }
+void release_key(uint8_t col, uint8_t row) { matrix[row] &= ~((matrix_row_t)1 << col); }
+
+bool matrix_is_on(uint8_t row, uint8_t col) { return (matrix[row] & ((matrix_row_t)1 << col)); }
 
 void clear_all_keys(void) { memset(matrix, 0, sizeof(matrix)); }
 

tests/test_common/test_fixture.cpp

@@ -12,6 +12,7 @@
 #include "test_logger.hpp"
 #include "test_matrix.h"
 #include "test_keymap_key.hpp"
+#include "timer.h"
 
 extern "C" {
 #include "action.h"
@@ -41,6 +42,7 @@ extern "C" uint16_t keymap_key_to_keycode(uint8_t layer, keypos_t position) {
 }
 
 void TestFixture::SetUpTestCase() {
+ test_logger.info() << "Tapping Term is " << +TAPPING_TERM << "ms" << std::endl;
  test_logger.info() << "TestFixture setup-up start." << std::endl;
 
  // The following is enough to bootstrap the values set in main
@@ -55,7 +57,10 @@ void TestFixture::SetUpTestCase() {
 
 void TestFixture::TearDownTestCase() {}
 
-TestFixture::TestFixture() { m_this = this; }
+TestFixture::TestFixture() {
+ m_this = this;
+ timer_clear();
+}
 
 TestFixture::~TestFixture() {
  test_logger.info() << "TestFixture clean-up start." << std::endl;
@@ -83,11 +88,9 @@ TestFixture::~TestFixture() {
  EXPECT_CALL(driver, send_keyboard_mock(_)).Times(0);
  idle_for(TAPPING_TERM * 10);
  testing::Mock::VerifyAndClearExpectations(&driver);
-
  m_this = nullptr;
 
  test_logger.info() << "TestFixture clean-up end." << std::endl;
-
  print_test_log();
 }
 
@@ -142,14 +145,13 @@ void TestFixture::get_keycode(const layer_t layer, const keypos_t position, uint
  FAIL() << "No key is mapped for layer " << +layer << " and (column,row) " << +position.col << "," << +position.row << ")";
 }
 
-void TestFixture::run_one_scan_loop() {
- keyboard_task();
- advance_time(1);
-}
+void TestFixture::run_one_scan_loop() { this->idle_for(1); }
 
 void TestFixture::idle_for(unsigned time) {
+ test_logger.trace() << "Running " << +time << " keyboard task loop(s)" << std::endl;
  for (unsigned i = 0; i < time; i++) {
- run_one_scan_loop();
+ keyboard_task();
+ advance_time(1);
  }
 }
 

tests/test_common/test_keymap_key.cpp

@@ -15,16 +15,27 @@
  */
 
 #include "test_keymap_key.hpp"
+#include <cstdint>
+#include "matrix.h"
 #include "test_logger.hpp"
 #include "gtest/gtest-message.h"
 #include "gtest/gtest.h"
+#include "timer.h"
 
 void KeymapKey::press() {
- test_logger.trace() << "Key pressed: (" << +this->position.col << "," << +this->position.row << ")" << std::endl;
+ EXPECT_FALSE(matrix_is_on(position.row, position.col)) << "Tried to press key (" << +this->position.col << "," << +this->position.row << ") "
+ << "that wasn't pressed before! Check the test code." << std::endl;
+
  press_key(this->position.col, this->position.row);
+ this->timestamp_pressed = timer_read32();
+ test_logger.trace() << "Key pressed: (" << +this->position.col << "," << +this->position.row << ")" << std::endl;
 }
 
 void KeymapKey::release() {
- test_logger.trace() << "Key released: (" << +this->position.col << "," << +this->position.row << ")" << std::endl;
+ EXPECT_TRUE(matrix_is_on(this->position.row, this->position.col)) << "Tried to release key (" << +this->position.col << "," << +this->position.row << ") "
+ << "that wasn't pressed before! Check the test code." << std::endl;
+
  release_key(this->position.col, this->position.row);
-}
+ uint32_t now = timer_read32();
+ test_logger.trace() << "Key released: (" << +this->position.col << "," << +this->position.row << ") was pressed for " << now - this->timestamp_pressed << "ms" << std::endl;
+}

tests/test_common/test_keymap_key.hpp

@@ -43,4 +43,5 @@ struct KeymapKey {
  assert(position.col <= MATRIX_COLS);
  assert(position.row <= MATRIX_ROWS);
  }
-};
+ uint32_t timestamp_pressed;
+};

tests/test_common/test_logger.cpp

@@ -14,26 +14,32 @@
  * along with this program. If not, see <http:https://www.gnu.org/licenses/>.
  */
 
+#include <iomanip>
 #include <iostream>
 #include "test_logger.hpp"
+#include "timer.h"
 
 TestLogger test_logger;
 
 TestLogger& TestLogger::info() {
  *this << "[ INFO ] ";
- return *this;
+ return this->timestamp();
 }
 
 TestLogger& TestLogger::trace() {
  *this << "[ TRACE ] ";
- return *this;
+ return this->timestamp();
 }
 
 TestLogger& TestLogger::error() {
  *this << "[ ERROR ] ";
- return *this;
+ return this->timestamp();
 }
 
+TestLogger& TestLogger::timestamp() {
+ *this << std::setw(4) << timer_read32() << " ";
+ return *this;
+}
 void TestLogger::reset() { this->m_log.str(""); };
 
 void TestLogger::print_log() { std::cerr << this->m_log.str(); }

tests/test_common/test_logger.hpp

@@ -29,7 +29,8 @@ class TestLogger : public std::ostream {
  void reset();
 
  private:
+ TestLogger& timestamp();
  std::stringbuf m_log;
 };
 
-extern TestLogger test_logger;
+extern TestLogger test_logger;