Tests: Added timestamps to log messages

tests/requirements/test/test_hal_timer.py

@@ -1,7 +1,7 @@
 import logging
 from typing import List
 
-from test_utils import finish_test, init_test
+from test_utils import finish_test, init_test, setup_logger
 
 TEST_NAME = "test-hal-timer"
 
@@ -22,15 +22,15 @@ def main():
     for _ in range(10):
         fast_irq_counts.append(int(rtt.receive_bytes_stream().decode()))
     avg_diffs_fast = average_difference(fast_irq_counts)
-    print(f"Average differences (fast clock): {avg_diffs_fast:.03f}")
+    logging.info(f"Average differences (fast clock): {avg_diffs_fast:.03f}")
 
     # After 10 messages, tasklet should disable the timer, so incoming IRQ counts
     # should not change
     stopped_irq_counts: List[int] = list()
     for _ in range(10):
         stopped_irq_counts.append(int(rtt.receive_bytes_stream().decode()))
     avg_diffs_stopped = average_difference(stopped_irq_counts)
-    print(f"Average differences (clock stopped): {avg_diffs_stopped:.03f}")
+    logging.info(f"Average differences (clock stopped): {avg_diffs_stopped:.03f}")
 
     # After another 10 messages, tasklet should switch timer's source to slower one
     # and enable it, returning IRQ count that's changing slower
@@ -39,18 +39,18 @@ def main():
         slow_irq_counts.append(int(rtt.receive_bytes_stream().decode()))
 
     avg_diffs_slow = average_difference(slow_irq_counts)
-    print(f"Average differences (slow clock): {avg_diffs_slow:.03f}")
+    logging.info(f"Average differences (slow clock): {avg_diffs_slow:.03f}")
 
     if avg_diffs_fast <= avg_diffs_slow:
-        print("TEST FAILED: FASTER CLOCK IS IN FACT SLOWER")
+        logging.critical("TEST FAILED: FASTER CLOCK IS IN FACT SLOWER")
         exit(2)
 
     if avg_diffs_stopped != 0:
-        print("TEST FAILED: CLOCK DID NOT STOP")
+        logging.critical("TEST FAILED: CLOCK DID NOT STOP")
 
     finish_test(ssh)
 
 
 if __name__ == "__main__":
-    logging.basicConfig(level=logging.INFO)
+    setup_logger()
     main()

tests/requirements/test/test_hal_watchdog.py

@@ -1,6 +1,6 @@
 import logging
 
-from test_utils import finish_test, init_test
+from test_utils import finish_test, init_test, setup_logger
 
 TEST_NAME = "test-hal-watchdog"
 
@@ -15,23 +15,25 @@ def main():
     ]
 
     for message in expected_messages:
-        received_message = rtt.receive_bytes_stream().decode()
-        print(received_message)
+        received_message = rtt.receive_string_stream()
+        logging.info(f"RTT> {received_message}")
         if received_message != message:
-            print(
+            logging.critical(
                 "TEST FAILED: UNEXPECTED MESSAGE RECEIVED "
                 f"(expecting {message}, got {received_message})"
             )
             finish_test(ssh)
             exit(2)
 
+    logging.info("Expecting a watchdog-induced MCU reset now...")
     # Default watchdog timeout is 16s. Watchdog in this test is set to 3s, but timeout must be
     # few seconds higher to compensate for communication delays and MCU clock inaccuracies.
     gdb.wait_for_reset(timeout=10)
+    logging.info("Watchdog-induced reset detected!")
 
     finish_test(ssh)
 
 
 if __name__ == "__main__":
-    logging.basicConfig(level=logging.INFO)
+    setup_logger()
     main()

tests/requirements/test/test_utils.py

@@ -18,6 +18,12 @@
 TARGET_NAME = "thumbv7em-none-eabihf"
 
 
+def setup_logger():
+    logging.basicConfig(
+        level=logging.INFO, format="[%(asctime)s] <%(levelname)s|%(name)s>: %(message)s"
+    )
+
+
 def init_test(test_name: str) -> Tuple[GDBClient, CalldwellRTTClient, SSHClient]:
     """Creates SSH connection to target board, initializes Calldwell"""
     project_path = TEST_BINS_DIRECTORY / test_name
@@ -38,7 +44,7 @@ def init_test(test_name: str) -> Tuple[GDBClient, CalldwellRTTClient, SSHClient]
     )
 
     if session is None:
-        logging.error("Test failed, cannot initialize Calldwell session")
+        logging.critical("Test failed, cannot initialize Calldwell session")
         exit(1)
 
     gdb, rtt = session
@@ -48,6 +54,7 @@ def init_test(test_name: str) -> Tuple[GDBClient, CalldwellRTTClient, SSHClient]
 
 
 def finish_test(ssh: SSHClient):
+    logging.info("TEST SUCCESSFUL!")
     logging.info("Finishing the test, cleaning up environment...")
     ssh.execute("pkill openocd")
     ssh.close()