IUT ready event timeout

[KKopyscinski]

Problem description:

There is possibility that after DUT reset we will not receive iut_ready_event, with socket.timeout error. In theory, this should trigger cleanup sequence and end test. This sequence is indeed triggering, but test execution is frozen and no retries/new tests are run.

Logs illustrating this issue are as follows:

2021-04-28 14:56:29,952 root DEBUG iutctl.py                 238   reset                     : About to reset DUT: 'nrfjprog -f nrf52 -r'
2021-04-28 14:56:30,804 root DEBUG iutctl_common.py          169   read                      : read
2021-04-28 14:56:50,810 root ERROR autoptsclient_common.py   757   run_test_case_thread_entry : 
Traceback (most recent call last):
  File "/home/codecoup/workspace/auto-pts/autoptsclient_common.py", line 739, in run_test_case_thread_entry
    test_case.pre_run()
  File "/home/codecoup/workspace/auto-pts/ptsprojects/testcase.py", line 749, in pre_run
    cmd.start()
  File "/home/codecoup/workspace/auto-pts/ptsprojects/testcase.py", line 256, in start
    self.func(*args, **self.kwds)
  File "/home/codecoup/workspace/auto-pts/ptsprojects/zephyr/iutctl.py", line 154, in wait_iut_ready_event
    tuple_hdr, tuple_data = self.btp_socket.read()
  File "/home/codecoup/workspace/auto-pts/pybtp/iutctl_common.py", line 188, in read
    raise socket.timeout
socket.timeout
2021-04-28 14:56:50,817 root DEBUG autoptsclient_common.py   692   get_error_code            : get_error_code returning error code 'BTP TIMEOUT' for exception timeout()
2021-04-28 14:56:51,817 root DEBUG testcase.py               756   post_run                  : post_run MESH MESH/NODE/FRND/LPN/BV-07-C BTP TIMEOUT
2021-04-28 14:56:51,817 root DEBUG testcase.py               242   start                     : Starting test function: class=<class 'ptsprojects.testcase.TestFuncCleanUp'>, func=<bound method Stack.cleanup of <ptsprojects.stack.Stack object at 0x7fce38209670>> start_wid=None stop_wid=None post_wid=None skip_call=None call_count=1 args=() kwds={}
2021-04-28 14:56:51,818 root DEBUG testcase.py               254   start                     : Test function parameters: args=(), kwds={}
2021-04-28 14:56:51,818 root DEBUG autoptsclient_common.py   290   clear_pending_responses   : CallbackThread.clear_pending_responses
2021-04-28 14:56:51,818 root DEBUG autoptsclient_common.py   290   clear_pending_responses   : CallbackThread.clear_pending_responses
2021-04-28 14:56:51,818 root DEBUG testcase.py               242   start                     : Starting test function: class=<class 'ptsprojects.testcase.TestFuncCleanUp'>, func=<bound method ZephyrCtl.stop of <ptsprojects.zephyr.iutctl.ZephyrCtl object at 0x7fce38209820>> start_wid=None stop_wid=None post_wid=None skip_call=None call_count=1 args=() kwds={}
2021-04-28 14:56:51,818 root DEBUG testcase.py               254   start                     : Test function parameters: args=(), kwds={}
2021-04-28 14:56:51,818 root DEBUG iutctl.py                 170   stop                      : <class 'ptsprojects.zephyr.iutctl.ZephyrCtl'>.stop

To reproduce:

The origin of this problem might be problem in closing socat process from previous test case, which would be hard to reproduce.
However, we can mimic the problem by opening communication with board on same port as socat process, after creating socat process, and before DUT restart, like this:

2021-04-29 08:04:12,432 root DEBUG iutctl.py                 73    start                     : Starting socat process: socat -x -v /dev/ttyACM0,rawer,b115200 UNIX-CONNECT:/tmp/bt-stack-tester
2021-04-29 08:04:12,434 root DEBUG iutctl_common.py          226   accept                    : accept
2021-04-29 08:04:12,436 root DEBUG testcase.py               242   start                     : Starting test function: class=<class 'ptsprojects.testcase.TestFunc'>, func=<bound method MynewtCtl.wait_iut_ready_event of <ptsprojects.mynewt.iutctl.MynewtCtl object at 0x7f5d7a419eb0>> start_wid=None stop_wid=None post_wid=None skip_call=None call_count=1 args=() kwds={}
2021-04-29 08:04:12,436 root DEBUG testcase.py               254   start                     : Test function parameters: args=(), kwds={}
2021-04-29 08:04:12,436 root DEBUG iutctl.py                 101   reset                     : <class 'ptsprojects.mynewt.iutctl.MynewtCtl'>.reset
2021-04-29 08:04:12,436 root DEBUG iutctl.py                 132   stop                      : <class 'ptsprojects.mynewt.iutctl.MynewtCtl'>.stop
2021-04-29 08:04:13,440 root DEBUG iutctl.py                 60    start                     : <class 'ptsprojects.mynewt.iutctl.MynewtCtl'>.start
2021-04-29 08:04:13,441 root DEBUG iutctl.py                 84    flush_serial              : <class 'ptsprojects.mynewt.iutctl.MynewtCtl'>.flush_serial
2021-04-29 08:04:14,445 root DEBUG iutctl.py                 73    start                     : Starting socat process: socat -x -v /dev/ttyACM0,rawer,b115200 UNIX-CONNECT:/tmp/bt-stack-tester
2021-04-29 08:04:14,451 root DEBUG iutctl_common.py          226   accept                    : accept
2021-04-29 08:04:14,455 root DEBUG iutctl.py                 84    flush_serial              : <class 'ptsprojects.mynewt.iutctl.MynewtCtl'>.flush_serial

Here we begin communication with DUT using pty-like tool (here was used screen /dev/ttyACM0 115200)

2021-04-29 08:04:15,458 root DEBUG iutctl.py                 186   reset                     : About to reset DUT: 'nrfjprog -f nrf52 -r'
2021-04-29 08:04:16,520 root DEBUG iutctl_common.py          169   read                      : read
2021-04-29 08:04:36,527 root ERROR autoptsclient_common.py   757   run_test_case_thread_entry : 
Traceback (most recent call last):
  File "/home/krzysiek/auto-pts/autoptsclient_common.py", line 739, in run_test_case_thread_entry
    test_case.pre_run()
  File "/home/krzysiek/auto-pts/ptsprojects/testcase.py", line 749, in pre_run
    cmd.start()
  File "/home/krzysiek/auto-pts/ptsprojects/testcase.py", line 256, in start
    self.func(*args, **self.kwds)
  File "/home/krzysiek/auto-pts/ptsprojects/mynewt/iutctl.py", line 115, in wait_iut_ready_event
    tuple_hdr, tuple_data = self.btp_socket.read()
  File "/home/krzysiek/auto-pts/pybtp/iutctl_common.py", line 188, in read
    raise socket.timeout
socket.timeout
2021-04-29 08:04:36,536 root DEBUG autoptsclient_common.py   692   get_error_code            : get_error_code returning error code 'BTP TIMEOUT' for exception timeout()

Now, autopts is frozen