tester/tftp: Fix recovery of timed out TFTP sessions

- Add support to retry the tftp session if the target has not
  started

- Add target handlers for the test directives to allow recovery
  on error

6 files changed, 184 insertions, 59 deletions

diff --git a/tester/rt/config.py b/tester/rt/config.py
index a9adfd8..61e8f0d 100644
--- a/tester/rt/config.py
+++ b/tester/rt/config.py
@@ -84,8 +84,10 @@ class file(config.file):
         self.kill_good = False
         self.kill_on_end = False
         self.test_label = None
-        self.target_reset_regx = None
         self.target_start_regx = None
+        self.target_reset_regx = None
+        self.restarts = 0
+        self.max_restarts = int(self.expand('%{max_restarts}'))
 
     def __del__(self):
         if self.console:
@@ -190,11 +192,12 @@ class file(config.file):
 
     def _output_length(self):
         self._lock()
-        if self.test_started:
-            l = len(self.output)
+        try:
+            if self.test_started:
+                l = len(self.output)
+                return l
+        finally:
             self._unlock()
-            return l
-        self._unlock()
         return 0
 
     def _capture_console(self, text):
@@ -354,15 +357,15 @@ class file(config.file):
         return None, None, None
 
     def _realtime_trace(self, text):
-        for l in text:
-            self._unlock()
-            try:
-                print(''.join(l))
-            except:
-                stacktraces.trace()
-                raise
-            finally:
-                self._lock()
+        self._unlock()
+        try:
+            for l in text:
+                log.output(''.join(l))
+        except:
+            stacktraces.trace()
+            raise
+        finally:
+            self._lock()
 
     def run(self):
         self.target_start_regx = self._target_regex('target_start_regex')
@@ -380,25 +383,36 @@ class file(config.file):
                     if e >= 0:
                         self.test_label = text[s + len('*** BEGIN OF TEST '):s + e + 3 - 1]
                     self._capture_console('test start: %s' % (self.test_label))
+                    self.process.target_start()
             ok_to_kill = '*** TEST STATE: USER_INPUT' in text or \
                          '*** TEST STATE: BENCHMARK' in text
             if ok_to_kill:
                 reset_target = True
             else:
                 reset_target = False
-            if self.test_started and self.target_start_regx is not None:
+            if self.target_start_regx is not None:
                 if self.target_start_regx.match(text):
-                    self._capture_console('target start detected')
-                    ok_to_kill = True
+                    if self.test_started:
+                        self._capture_console('target start detected')
+                        ok_to_kill = True
+                    else:
+                        self.restarts += 1
+                        if self.restarts > self.max_restarts:
+                            self._capture_console('target restart maximum count reached')
+                            ok_to_kill = True
+                        else:
+                            self.process.target_restart(self.test_started)
             if not reset_target and self.target_reset_regx is not None:
                 if self.target_reset_regx.match(text):
                     self._capture_console('target reset condition detected')
                     self._target_command('reset')
+                    self.process.target_reset(self.test_started)
             if self.kill_on_end:
                 if not ok_to_kill and '*** END OF TEST ' in text:
                     self._capture_console('test end: %s' % (self.test_label))
                     if self.test_label is not None:
                         ok_to_kill = '*** END OF TEST %s ***' % (self.test_label) in text
+                    self.process.target_end()
             text = [(self.console_prefix, l) for l in text.replace(chr(13), '').splitlines()]
             if self.output is not None:
                 if self.realtime_trace:
diff --git a/tester/rt/exe.py b/tester/rt/exe.py
index 5655073..13b9686 100644
--- a/tester/rt/exe.py
+++ b/tester/rt/exe.py
@@ -170,3 +170,15 @@ class exe(object):
             self._kill()
         finally:
             self._unlock('_kill')
+
+    def target_restart(self, started):
+        pass
+
+    def target_reset(self, started):
+        pass
+
+    def target_start(self):
+        pass
+
+    def target_end(self):
+        pass
diff --git a/tester/rt/gdb.py b/tester/rt/gdb.py
index 4abbca5..674c706 100644
--- a/tester/rt/gdb.py
+++ b/tester/rt/gdb.py
@@ -284,6 +284,18 @@ class gdb(object):
         finally:
             self._unlock('_kill')
 
+    def target_restart(self, started):
+        pass
+
+    def target_reset(self, started):
+        pass
+
+    def target_start(self):
+        pass
+
+    def target_end(self):
+        pass
+
     def gdb_expect(self):
         if self.trace:
             print('}}} gdb-expect')
diff --git a/tester/rt/tftp.py b/tester/rt/tftp.py
index 49bdb29..5a1c7b7 100644
--- a/tester/rt/tftp.py
+++ b/tester/rt/tftp.py
@@ -41,6 +41,7 @@ import time
 import sys
 
 from rtemstoolkit import error
+from rtemstoolkit import log
 from rtemstoolkit import reraise
 
 import tester.rt.tftpserver
@@ -68,54 +69,69 @@ class tftp(object):
         self.timeout = None
         self.test_too_long = None
         self.timer = None
+        self.opened = False
         self.running = False
         self.finished = False
         self.caught = None
+        self.target_state = 'reset'
 
     def _lock(self, msg):
         if self.lock_trace:
-            print('|[   LOCK:%s ]|' % (msg))
+            log.trace('|[   LOCK:%s ]|' % (msg))
         self.lock.acquire()
+        if self.lock_trace:
+            log.trace('|[   LOCK:%s done ]|' % (msg))
 
     def _unlock(self, msg):
         if self.lock_trace:
-            print('|] UNLOCK:%s [|' % (msg))
+            log.trace('|] UNLOCK:%s [|' % (msg))
         self.lock.release()
+        if self.lock_trace:
+            log.trace('|[ UNLOCK:%s done ]|' % (msg))
+
+    def _trace(self, text):
+        if log.tracing:
+            log.trace('] tftp: ' + text)
+
+    def _console(self, text):
+        if self.console:
+            self.console(text)
+
+    def _set_target_state(self, state):
+        self._trace('set state: ' + state)
+        self.target_state = state
 
     def _finished(self):
         self.server = None
         self.exe = None
 
-    def _stop(self):
+    def _stop(self, finished = True):
         try:
-            if self.server:
+            if self.server is not None:
                 self.server.stop()
-            self.finished = True
+            self.finished = Finished
         except:
             pass
 
+    def _run_finished(self):
+        while self.opened and (self.running or not self.finished):
+            self._unlock('_run_finished')
+            time.sleep(0.2)
+            self._lock('_run_finished')
+
     def _kill(self):
         self._stop()
-        while self.running or not self.finished:
-            self._unlock('_kill')
-            time.sleep(0.1)
-            self._lock('_kill')
+        self._run_finished()
 
     def _timeout(self):
         self._stop()
-        while self.running or not self.finished:
-            self._unlock('_timeout')
-            time.sleep(0.1)
-            self._lock('_timeout')
+        self._run_finished()
         if self.timeout is not None:
             self.timeout()
 
     def _test_too_long(self):
         self._stop()
-        while self.running or not self.finished:
-            self._unlock('_test_too_long')
-            time.sleep(0.1)
-            self._lock('_test_too_long')
+        self._run_finished()
         if self.test_too_long is not None:
             self.test_too_long()
 
@@ -125,25 +141,21 @@ class tftp(object):
         self.exe = None
         self._unlock('_exe_handle')
         if exe is not None:
-            if self.console:
-                self.console('tftp: %s' % (exe))
+            self._console('tftp: %s' % (exe))
             return open(exe, "rb")
-        if self.console:
-            self.console('tftp: re-requesting exe; target must have reset')
+        self._console('tftp: re-requesting exe; target must have reset')
         self._stop()
         return None
 
-    def _listener(self):
-        self._lock('_listener')
-        exe = self.exe
-        self.exe = None
-        self._unlock('_listener')
+    def _listener(self, exe):
         self.server = tester.rt.tftpserver.tftp_server(host = 'all',
                                                        port = self.port,
                                                        timeout = 10,
                                                        forced_file = exe,
                                                        sessions = 1)
         try:
+            if log.tracing:
+                self.server.trace_packets()
             self.server.start()
             self.server.run()
         except:
@@ -151,20 +163,44 @@ class tftp(object):
             raise
 
     def _runner(self):
+        self._trace('session: start')
         self._lock('_runner')
-        self.running = True
+        exe = self.exe
+        self.exe = None
         self._unlock('_runner')
         caught = None
         try:
-            self._listener()
+            self._lock('_runner')
+            state = self.target_state
+            self._unlock('_runner')
+            self._trace('runner: ' + state)
+            while state not in ['shutdown', 'finished']:
+                if state != 'running':
+                    self._trace('listening: begin: ' + state)
+                    self._listener(exe)
+                    self._lock('_runner')
+                    if self.target_state == 'booting':
+                        self._set_target_state('loaded')
+                    self._unlock('_runner')
+                    self._trace('listening: end: ' + state)
+                else:
+                    time.sleep(0.25)
+                self._lock('_runner')
+                state = self.target_state
+                self._unlock('_runner')
         except:
             caught = sys.exc_info()
+            self._trace('session: exception')
         self._lock('_runner')
-        self.running = False
+        self._trace('runner: ' + self.target_state)
         self.caught = caught
+        self.finished = True
+        self.running = False
         self._unlock('_runner')
+        self._trace('session: end')
 
     def open(self, executable, port, output_length, console, timeout):
+        self._trace('open: start')
         self._lock('_open')
         if self.exe is not None:
             self._unlock('_open')
@@ -174,13 +210,16 @@ class tftp(object):
         self.console = console
         self.port = port
         self.exe = executable
-        if self.console:
-            self.console('tftp: exe: %s' % (executable))
         self.timeout = timeout[2]
         self.test_too_long = timeout[3]
+        self.opened = True
+        self.running = True
         self.listener = threading.Thread(target = self._runner,
                                          name = 'tftp-listener')
+        self._unlock('_open: start listner')
+        self._console('tftp: exe: %s' % (executable))
         self.listener.start()
+        self._lock('_open: start listner')
         step = 0.25
         period = timeout[0]
         seconds = timeout[1]
@@ -188,6 +227,7 @@ class tftp(object):
         while not self.finished and period > 0 and seconds > 0:
             if not self.running and self.caught:
                 break
+            self._unlock('_open: loop')
             current_length = self.output_length()
             if output_length != current_length:
                 period = timeout[0]
@@ -201,9 +241,9 @@ class tftp(object):
                 period = 0
             else:
                 period -= step
-            self._unlock('_open')
             time.sleep(step)
-            self._lock('_open')
+            self._lock('_open: loop')
+        self._trace('open: finished')
         if not self.finished:
             if period == 0:
                 self._timeout()
@@ -216,10 +256,55 @@ class tftp(object):
             reraise.reraise(*caught)
 
     def kill(self):
+        self._trace('kill')
         self._lock('kill')
+        self._set_target_state('shutdown')
         self._kill()
         self._unlock('kill')
 
+    def target_restart(self, started):
+        self._trace('target: restart: %d' % (started))
+        self._lock('target_restart')
+        try:
+            if not started:
+                if self.server is not None:
+                    self._trace('server: stop')
+                    self._stop(finished = False)
+                    self._trace('server: stop done')
+                state = 'booting'
+            else:
+                state = 'shutdown'
+            self._set_target_state(state)
+        finally:
+            self._unlock('target_restart')
+
+    def target_reset(self, started):
+        self._trace('target: reset: %d' % (started))
+        self._lock('target_reset')
+        try:
+            if not started:
+                if self.server is not None:
+                    self._trace('server: stop')
+                    self.server.stop()
+                state = 'booting'
+            else:
+                state = 'shutdown'
+            self._set_target_state(state)
+        finally:
+            self._unlock('target_reset')
+
+    def target_start(self):
+        self._trace('target: start')
+        self._lock('target_start')
+        self._set_target_state('running')
+        self._unlock('target_start')
+
+    def target_end(self):
+        self._trace('target: end')
+        self._lock('target_end')
+        self._set_target_state('finished')
+        self._unlock('target_end')
+
 if __name__ == "__main__":
     import sys
     if len(sys.argv) > 1:
diff --git a/tester/rt/tftpserver.py b/tester/rt/tftpserver.py
index 8a63546..92cd1fd 100644
--- a/tester/rt/tftpserver.py
+++ b/tester/rt/tftpserver.py
@@ -384,7 +384,8 @@ class udp_handler(socketserver.BaseRequestHandler):
     def _notice(self, text):
         if self.server.tftp.notices:
             log.notice(text)
-        log.output(text)
+        if log.tracing:
+            log.trace(text)
 
     def handle_session(self, index):
         '''Handle the TFTP session data.'''
@@ -425,7 +426,7 @@ class udp_handler(socketserver.BaseRequestHandler):
                             log.trace(
                                 ' > ' +
                                 session.decode(address[0], address[1], data))
-                    except socket.timout as sto:
+                    except socket.timeout as sto:
                         self._notice('] tftp: %d: timeout: %s' % (index, client))
                         continue
                     except socket.error as serr:
@@ -529,14 +530,14 @@ class tftp_server(object):
 
     def stop(self):
         '''Stop the TFTP server and close the server port.'''
-        self._lock()
-        try:
-            if self.server is not None:
-                self.server.shutdown()
-                self.server.server_close()
+        if self.server is not None:
+            self.server.server_close()
+            self.server.shutdown()
+            self._lock()
+            try:
                 self.server = None
-        finally:
-            self._unlock()
+            finally:
+                self._unlock()
 
     def run(self):
         '''Run the TFTP server for the specified number of sessions.'''
diff --git a/tester/rtems/testing/testing.mc b/tester/rtems/testing/testing.mc
index d03ea6d..98cdc0a 100644
--- a/tester/rtems/testing/testing.mc
+++ b/tester/rtems/testing/testing.mc
@@ -53,6 +53,7 @@ _rtscripts:           none,    none,     '%{_rtbase}/rtems/testing'
 # Defaults
 timeout:              none,    none,     '180'  # seconds
 max_test_period:      none,    none,     '300'  # seconds
+max_restarts:         none,    none,     '3'
 
 # Tests detected as invalid that are valid
 invalid_tests:        none,    none,     '''minimum.exe'''