bot: improve rtt log

This should stop rtt read process only if we are sure that test case has
ended and there is no more data to send.
Also RTT logger timeout param is added which is configurable via
command line or config_prj.py

autopts/bot/common.py

@@ -121,6 +121,7 @@ def __init__(self, args, **kwargs):
         self.pylink_reset = args.get('pylink_reset', False)
         self.max_server_restart_time = args.get('max_server_restart_time', MAX_SERVER_RESTART_TIME)
         self.use_backup = args.get('use_backup', False)
+        self.rtt_logger_timeout = args.get('rtt_logger_timeout', 0.1)
 
         if self.ykush or self.active_hub_server:
             self.usb_replug_available = True

autopts/ptsprojects/mynewt/iutctl.py

@@ -20,6 +20,7 @@
 import os
 import sys
 import serial
+import time
 
 from autopts.pybtp import defs, btp
 from autopts.ptsprojects.boards import Board, get_debugger_snr, tty_to_com
@@ -52,6 +53,7 @@ def __init__(self, args):
         self.debugger_snr = get_debugger_snr(self.tty_file) \
             if args.debugger_snr is None else args.debugger_snr
         self.board = Board(args.board_name, self)
+        self.rtt_logger_timeout = args.rtt_logger_timeout
         self.socat_process = None
         self.socket_srv = None
         self.btp_socket = None
@@ -138,19 +140,17 @@ def rtt_logger_start(self):
                                     '_iutctl.log')
             self.rtt_logger.start('Terminal', log_file, self.device_core, self.debugger_snr)
 
-    def rtt_logger_stop(self):
+    def rtt_logger_stop(self, reset):
         if self.rtt_logger:
-            self.rtt_logger.stop()
+            self.rtt_logger.stop(reset, self.rtt_logger_timeout)
 
     def reset(self):
         """Restart IUT related processes and reset the IUT"""
         log("%s.%s", self.__class__, self.reset.__name__)
 
-        self.stop()
+        self.stop(reset=True)
         self.start(self.test_case)
         self.flush_serial()
-
-        self.rtt_logger_stop()
         self.btmon_stop()
 
         if not self.gdb:
@@ -180,7 +180,7 @@ def wait_iut_ready_event(self):
     def get_supported_svcs(self):
         btp.read_supp_svcs()
 
-    def stop(self):
+    def stop(self, reset=False):
         """Powers off the Mynewt OS"""
         log("%s.%s", self.__class__, self.stop.__name__)
 
@@ -199,7 +199,7 @@ def stop(self):
             self.iut_log_file.close()
             self.iut_log_file = None
 
-        self.rtt_logger_stop()
+        self.rtt_logger_stop(reset)
         self.btmon_stop()
 
         if self.socat_process:

autopts/ptsprojects/zephyr/iutctl.py

@@ -70,6 +70,7 @@ def __init__(self, args):
         self.kernel_image = args.kernel_image
         self.tty_file = args.tty_file
         self.hci = args.hci
+        self.rtt_logger_timeout = args.rtt_logger_timeout
         self.native = None
         self.gdb = args.gdb
         self.is_running = False
@@ -203,18 +204,17 @@ def rtt_logger_start(self):
                                     '_iutctl.log')
             self.rtt_logger.start('Logger', log_file, self.device_core, self.debugger_snr)
 
-    def rtt_logger_stop(self):
+    def rtt_logger_stop(self, reset):
         if self.rtt_logger:
-            time.sleep(0.1)  # Make sure all logs have been collected, in case test failed early.
-            self.rtt_logger.stop()
+            self.rtt_logger.stop(reset, self.rtt_logger_timeout)
 
     def wait_iut_ready_event(self, reset=True):
         """Wait until IUT sends ready event after power up"""
         stack = get_stack()
 
         if reset:
             # For HW, the IUT ready event is triggered at board.reset()
-            self.stop()
+            self.stop(reset)
             # For QEMU, the IUT ready event is sent at startup of the process.
             self.start(self.test_case)
 
@@ -225,7 +225,7 @@ def wait_iut_ready_event(self, reset=True):
                 # two IUT events may be received because of cleanup.
                 stack.core.event_queues[defs.CORE_EV_IUT_READY].clear()
                 if not ev:
-                    self.stop()
+                    self.stop(reset)
                     raise Exception('IUT ready event NOT received!')
 
             log("IUT ready event received OK")
@@ -244,14 +244,14 @@ def hw_reset(self):
             if len(stack.core.event_queues[defs.CORE_EV_IUT_READY]) == 0:
                 self.board.reset()
 
-    def stop(self):
+    def stop(self, reset=False):
         """Powers off the Zephyr OS"""
         log("%s.%s", self.__class__, self.stop.__name__)
 
         if not self.is_running:
             return
 
-        self.rtt_logger_stop()
+        self.rtt_logger_stop(reset)
         self.btmon_stop()
 
         stack = get_stack()

autopts/rtt.py

@@ -38,6 +38,8 @@ class RTT:
     def __init__(self):
         self.read_thread = None
         self.stop_thread = threading.Event()
+        self.rtt_stop = False
+        self.test_end = False
         pylink.logger.setLevel(logging.WARNING)
 
     def _get_buffer_index(self, buffer_name):
@@ -57,14 +59,22 @@ def _get_buffer_index(self, buffer_name):
             if buf.name == buffer_name:
                 return buf_index
 
-    @staticmethod
-    def _read_from_buffer(jlink, buffer_index, stop_thread, user_callback, user_data):
+    def _read_from_buffer(self, jlink, buffer_index, stop_thread, user_callback, user_data):
+        count = 0
+        threshold = 5
         try:
             while not stop_thread.is_set() and jlink.connected() and not get_global_end():
                 byte_list = jlink.rtt_read(buffer_index, 1024)
                 if len(byte_list) > 0:
+                    count = 0
                     user_callback(bytes(byte_list), user_data)
-        except BaseException:
+                elif self.test_end:
+                    count += 1
+                    if count >= threshold:
+                        # we have reached the threshold for consecutive empty reads, we can stop rtt_read
+                        self.rtt_stop = True
+        except BaseException as e:
+            self.rtt_stop = True
             pass  # JLink closed
 
     def init_jlink(self, device_core, debugger_snr):
@@ -233,9 +243,23 @@ def start(self, buffer_name, log_filename, device_core, debugger_snr):
         self.log_file = open(log_filename, 'ab')
         self.rtt_reader.start(buffer_name, device_core, debugger_snr, self._on_line_read_callback, (self.log_file,))
 
-    def stop(self):
+    def stop_timer(self):
+        # timeout reached
+        self.rtt_reader.rtt_stop = True
+
+    def stop(self, reset, timeout=0.1):
         log("%s.%s", self.__class__, self.stop.__name__)
-        self.rtt_reader.stop()
+
+        if reset:
+            self.rtt_reader.stop()
+        else:
+            self.rtt_reader.test_end = True
+            # let's wait until stopping rtt reader; timeout is configurable
+            timer = threading.Timer(timeout, self.stop_timer)
+            timer.start()
+            while not self.rtt_reader.rtt_stop:
+                time.sleep(0.1)
+            self.rtt_reader.stop()
 
         if self.log_file:
             self.log_file.close()

cliparser.py

@@ -155,6 +155,9 @@ def __init__(self, cli_support=None, board_names=None, add_help=True):
                               "Requires rtt support on IUT.",
                               action='store_true', default=False)
 
+            self.add_argument("--rtt_logger_timeout", nargs='?', type=float, default=0.1,
+                              help="Timeout for rtt logger to make sure all logs have been collected")
+
             self.add_argument("--gdb",
                               help="Skip board resets to avoid gdb server disconnection.",
                               action='store_true', default=False)