Repository: google/mobly

Issue:
Procedure functions triggered incorrectly
If a test throws an exception, and the teardown also throws an exception, `on_fail` is executed twice.

Discussion:
dthkao: 



Review status: 0 of 2 files reviewed at latest revision, 2 unresolved discussions.

---

*[mobly/base_test.py, line 359 at r1](https://reviewable.io:443/reviews/google/mobly/263#-Kp0u61nmBZ4dqzUVPiF:-Kp0u61oruK5KEpK27tn:b982v3x) ([raw file](https://github.com/google/mobly/blob/581a59e46299149554ab6e9c94da99a3868d0258/mobly/base_test.py#L359)):*
> ```Python
>                 except Exception as e:
>                     logging.exception(e)
>                     tr_record.add_error('teardown_test', e)
> ```

So this is a deeper issue, but if a test fails in the test case, and is marked as fail, and then teardown throws an error because part of the test wasn't executed, the result now becomes an error. Is that intended?

---

*[mobly/base_test.py, line 378 at r1](https://reviewable.io:443/reviews/google/mobly/263#-Kp0sYZQ6VbNc8OP1KcQ:-Kp0sYZQ6VbNc8OP1KcR:bgoqojn) ([raw file](https://github.com/google/mobly/blob/581a59e46299149554ab6e9c94da99a3868d0258/mobly/base_test.py#L378)):*
> ```Python
>             tr_record.test_pass()
>         finally:
>             if tr_record.result in (records.TestResultEnums.TEST_RESULT_ERROR,
> ```

Tangential, but is there any need for a distinction between what should be done if an error occurred vs a failure? Do we need a self.on_error()?

---


*Comments from [Reviewable](https://reviewable.io:443/reviews/google/mobly/263)*
<!-- Sent from Reviewable.io -->

xpconanfan: 



Review status: 0 of 2 files reviewed at latest revision, 2 unresolved discussions.

---

*[mobly/base_test.py, line 359 at r1](https://reviewable.io:443/reviews/google/mobly/263#-Kp0u61nmBZ4dqzUVPiF:-Kp0zsfLmcc91mE7p0S_:b-vlp9v4) ([raw file](https://github.com/google/mobly/blob/581a59e46299149554ab6e9c94da99a3868d0258/mobly/base_test.py#L359)):*
<details><summary><i>Previously, dthkao (David T.H. Kao) wrote…</i></summary><blockquote>

So this is a deeper issue, but if a test fails in the test case, and is marked as fail, and then teardown throws an error because part of the test wasn't executed, the result now becomes an error. Is that intended?
</blockquote></details>

This has always been the expected behavior and is not changed in this PR.
We specifically did this to be consistent with pyunit.

---

*[mobly/base_test.py, line 378 at r1](https://reviewable.io:443/reviews/google/mobly/263#-Kp0sYZQ6VbNc8OP1KcQ:-Kp1-4WKVsMsfpArDYuc:b7r6m37) ([raw file](https://github.com/google/mobly/blob/581a59e46299149554ab6e9c94da99a3868d0258/mobly/base_test.py#L378)):*
<details><summary><i>Previously, dthkao (David T.H. Kao) wrote…</i></summary><blockquote>

Tangential, but is there any need for a distinction between what should be done if an error occurred vs a failure? Do we need a self.on_error()?
</blockquote></details>

We specifically removed `on_error` at one point...
Because we found out that everybdoy just duped the code between on_fail and on_error with no difference...

---


*Comments from [Reviewable](https://reviewable.io:443/reviews/google/mobly/263)*
<!-- Sent from Reviewable.io -->


Patch:
diff --git a/mobly/controllers/android_device_lib/callback_handler.py b/mobly/controllers/android_device_lib/callback_handler.py
index 4207f47..1ab67d8 100644
--- a/mobly/controllers/android_device_lib/callback_handler.py
+++ b/mobly/controllers/android_device_lib/callback_handler.py
@@ -83,13 +83,14 @@ class CallbackHandler(object):
                     (timeout, MAX_TIMEOUT))
             timeout *= 1000  # convert to milliseconds for java side
         try:
-            raw_event = self._event_client.eventWaitAndGet(self._id,
-                                                           event_name, timeout)
+            raw_event = self._event_client.eventWaitAndGet(
+                self._id, event_name, timeout)
         except Exception as e:
             if 'EventSnippetException: timeout.' in str(e):
                 raise TimeoutError(
-                    'Timeout waiting for event "%s" triggered by %s (%s).' %
-                    (event_name, self._method_name, self._id))
+                    'Timed out after waiting %ss for event "%s" triggered by'
+                    ' %s (%s).' % (timeout, event_name, self._method_name,
+                                   self._id))
             raise
         return snippet_event.from_dict(raw_event)
 
diff --git a/mobly/controllers/android_device_lib/snippet_client.py b/mobly/controllers/android_device_lib/snippet_client.py
index 3d85e40..f7f473b 100644
--- a/mobly/controllers/android_device_lib/snippet_client.py
+++ b/mobly/controllers/android_device_lib/snippet_client.py
@@ -24,15 +24,27 @@ _INSTRUMENTATION_RUNNER_PACKAGE = (
     'com.google.android.mobly.snippet.SnippetRunner')
 
 # TODO(adorokhine): delete this in Mobly 1.6 when snippet v0 support is removed.
-_LAUNCH_CMD_V0 = ('am instrument -w -e action start -e port %s %s/' +
+_LAUNCH_CMD_V0 = ('%s am instrument -w -e action start -e port %s %s/' +
                   _INSTRUMENTATION_RUNNER_PACKAGE)
 
 _LAUNCH_CMD_V1 = (
-    'am instrument -w -e action start %s/' + _INSTRUMENTATION_RUNNER_PACKAGE)
+    '%s am instrument -w -e action start %s/' + _INSTRUMENTATION_RUNNER_PACKAGE)
 
 _STOP_CMD = (
     'am instrument -w -e action stop %s/' + _INSTRUMENTATION_RUNNER_PACKAGE)
 
+# Test that uses UiAutomation requires the shell session to be maintained while
+# test is in progress. However, this requirement does not hold for the test that
+# deals with device USB disconnection (Once device disconnects, the shell
+# session that started the instrument ends, and UiAutomation fails with error:
+# "UiAutomation not connected"). To keep the shell session and redirect
+# stdin/stdout/stderr, use "setsid" or "nohup" while launching the
+# instrumentation test. Because these commands may not be available in every
+# android system, try to use them only if exists.
+_SETSID_COMMAND = 'setsid'
+
+_NOHUP_COMMAND = 'nohup'
+
 # Maximum time to wait for a v0 snippet to start on the device (10 minutes).
 # TODO(adorokhine): delete this in Mobly 1.6 when snippet v0 support is removed.
 _APP_START_WAIT_TIME_V0 = 10 * 60
@@ -60,7 +72,7 @@ class SnippetClient(jsonrpc_client_base.JsonRpcClientBase):
 
     def __init__(self, package, adb_proxy, log=logging.getLogger()):
         """Initializes a SnippetClient.
-  
+
         Args:
             package: (str) The package name of the apk where the snippets are
                      defined.
@@ -77,13 +89,14 @@ class SnippetClient(jsonrpc_client_base.JsonRpcClientBase):
         """Overrides superclass. Launches a snippet app and connects to it."""
         self._check_app_installed()
 
+        persists_shell_cmd = self._get_persist_command()
         # Try launching the app with the v1 protocol. If that fails, fall back
         # to v0 for compatibility. Use info here so people know exactly what's
         # happening here, which is helpful since they need to create their own
         # instrumentations and manifest.
         self.log.info('Launching snippet apk %s with protocol v1',
                       self.package)
-        cmd = _LAUNCH_CMD_V1 % self.package
+        cmd = _LAUNCH_CMD_V1 % (persists_shell_cmd, self.package)
         start_time = time.time()
         self._proc = self._do_start_app(cmd)
 
@@ -106,7 +119,7 @@ class SnippetClient(jsonrpc_client_base.JsonRpcClientBase):
             # Reuse the host port as the device port in v0 snippet. This isn't
             # safe in general, but the protocol is deprecated.
             self.device_port = self.host_port
-            cmd = _LAUNCH_CMD_V0 % (self.device_port, self.package)
+            cmd = _LAUNCH_CMD_V0 % (persists_shell_cmd, self.device_port, self.package)
             self._proc = self._do_start_app(cmd)
             self._connect_to_v0()
             self._launch_version = 'v0'
@@ -291,3 +304,17 @@ class SnippetClient(jsonrpc_client_base.JsonRpcClientBase):
                 return line
             self.log.debug('Discarded line from instrumentation output: "%s"',
                            line)
+
+    def _get_persist_command(self):
+        """Check availability and return path of command if available."""
+        for command in [_SETSID_COMMAND, _NOHUP_COMMAND]:
+            try:
+                if command in self._adb.shell('which %s' % command):
+                    return command
+            except adb.AdbError:
+                continue
+        self.log.warning('No %s and %s commands available to launch instrument '
+                         'persistently, tests that depend on UiAutomator and '
+                         'at the same time performs USB disconnection may fail',
+                         _SETSID_COMMAND, _NOHUP_COMMAND)
+        return ''


Test patch:
diff --git a/mobly/base_test.py b/mobly/base_test.py
index b3ccf43..7353afd 100644
--- a/mobly/base_test.py
+++ b/mobly/base_test.py
@@ -357,14 +357,11 @@ class BaseTestClass(object):
                 except Exception as e:
                     logging.exception(e)
                     tr_record.add_error('teardown_test', e)
-                    self._exec_procedure_func(self._on_fail, tr_record)
         except (signals.TestFailure, AssertionError) as e:
             tr_record.test_fail(e)
-            self._exec_procedure_func(self._on_fail, tr_record)
         except signals.TestSkip as e:
             # Test skipped.
             tr_record.test_skip(e)
-            self._exec_procedure_func(self._on_skip, tr_record)
         except (signals.TestAbortClass, signals.TestAbortAll) as e:
             # Abort signals, pass along.
             tr_record.test_fail(e)
@@ -372,15 +369,19 @@ class BaseTestClass(object):
         except signals.TestPass as e:
             # Explicit test pass.
             tr_record.test_pass(e)
-            self._exec_procedure_func(self._on_pass, tr_record)
         except Exception as e:
             # Exception happened during test.
             tr_record.test_error(e)
-            self._exec_procedure_func(self._on_fail, tr_record)
         else:
             tr_record.test_pass()
-            self._exec_procedure_func(self._on_pass, tr_record)
         finally:
+            if tr_record.result in (records.TestResultEnums.TEST_RESULT_ERROR,
+                                    records.TestResultEnums.TEST_RESULT_FAIL):
+                self._exec_procedure_func(self._on_fail, tr_record)
+            elif tr_record.result == records.TestResultEnums.TEST_RESULT_PASS:
+                self._exec_procedure_func(self._on_pass, tr_record)
+            elif tr_record.result == records.TestResultEnums.TEST_RESULT_SKIP:
+                self._exec_procedure_func(self._on_skip, tr_record)
             self.results.add_record(tr_record)
 
     def _assert_function_name_in_stack(self, expected_func_name):
diff --git a/tests/mobly/base_test_test.py b/tests/mobly/base_test_test.py
index db615dd..35c29f2 100755
--- a/tests/mobly/base_test_test.py
+++ b/tests/mobly/base_test_test.py
@@ -201,7 +201,12 @@ class BaseTestTest(unittest.TestCase):
         on_fail_call_check.assert_called_once_with("haha")
 
     def test_setup_test_fail_by_exception(self):
+        mock_on_fail = mock.Mock()
+
         class MockBaseTest(base_test.BaseTestClass):
+            def on_fail(self, *args):
+                mock_on_fail('on_fail')
+
             def setup_test(self):
                 raise Exception(MSG_EXPECTED_EXCEPTION)
 
@@ -211,6 +216,7 @@ class BaseTestTest(unittest.TestCase):
 
         bt_cls = MockBaseTest(self.mock_test_cls_configs)
         bt_cls.run(test_names=["test_something"])
+        mock_on_fail.assert_called_once_with('on_fail')
         actual_record = bt_cls.results.error[0]
         self.assertEqual(actual_record.test_name, self.mock_test_name)
         self.assertEqual(actual_record.details, MSG_EXPECTED_EXCEPTION)
@@ -328,6 +334,9 @@ class BaseTestTest(unittest.TestCase):
             def teardown_test(self):
                 my_mock("teardown_test")
 
+            def on_pass(self, test_name, begin_time):
+                never_call()
+
             def test_something(self):
                 raise Exception(MSG_EXPECTED_EXCEPTION)
 
@@ -349,6 +358,9 @@ class BaseTestTest(unittest.TestCase):
             def on_fail(self, test_name, begin_time):
                 my_mock("on_fail")
 
+            def on_pass(self, test_name, begin_time):
+                never_call()
+
             def teardown_test(self):
                 raise Exception(MSG_EXPECTED_EXCEPTION)
 
@@ -373,6 +385,9 @@ class BaseTestTest(unittest.TestCase):
             def on_fail(self, test_name, begin_time):
                 my_mock("on_fail")
 
+            def on_pass(self, test_name, begin_time):
+                never_call()
+
             def test_something(self):
                 asserts.assert_true(False, MSG_EXPECTED_EXCEPTION)
 
@@ -387,6 +402,35 @@ class BaseTestTest(unittest.TestCase):
                             "Requested 1, Skipped 0")
         self.assertEqual(bt_cls.results.summary_str(), expected_summary)
 
+    def test_on_fail_executed_if_both_test_and_teardown_test_fails(self):
+        on_fail_mock = mock.MagicMock()
+
+        class MockBaseTest(base_test.BaseTestClass):
+            def on_fail(self, test_name, begin_time):
+                on_fail_mock("on_fail")
+
+            def on_pass(self, test_name, begin_time):
+                never_call()
+
+            def teardown_test(self):
+                raise Exception(MSG_EXPECTED_EXCEPTION + 'ha')
+
+            def test_something(self):
+                raise Exception(MSG_EXPECTED_EXCEPTION)
+
+        bt_cls = MockBaseTest(self.mock_test_cls_configs)
+        bt_cls.run()
+        on_fail_mock.assert_called_once_with("on_fail")
+        actual_record = bt_cls.results.error[0]
+        self.assertEqual(actual_record.test_name, self.mock_test_name)
+        self.assertEqual(actual_record.details, MSG_EXPECTED_EXCEPTION)
+        self.assertEqual(actual_record.extra_errors,
+                         {'teardown_test': 'This is an expected exception.ha'})
+        self.assertIsNone(actual_record.extras)
+        expected_summary = ("Error 1, Executed 1, Failed 0, Passed 0, "
+                            "Requested 1, Skipped 0")
+        self.assertEqual(bt_cls.results.summary_str(), expected_summary)
+
     def test_on_fail_executed_if_test_setup_fails_by_exception(self):
         my_mock = mock.MagicMock()
 
diff --git a/tests/mobly/controllers/android_device_lib/callback_handler_test.py b/tests/mobly/controllers/android_device_lib/callback_handler_test.py
index a701d51..f288ef3 100755
--- a/tests/mobly/controllers/android_device_lib/callback_handler_test.py
+++ b/tests/mobly/controllers/android_device_lib/callback_handler_test.py
@@ -34,6 +34,7 @@ MOCK_RAW_EVENT = {
 class CallbackHandlerTest(unittest.TestCase):
     """Unit tests for mobly.controllers.android_device_lib.callback_handler.
     """
+
     def test_timeout_value(self):
         self.assertGreaterEqual(jsonrpc_client_base._SOCKET_READ_TIMEOUT,
                                 callback_handler.MAX_TIMEOUT)
@@ -64,9 +65,9 @@ class CallbackHandlerTest(unittest.TestCase):
             event_client=mock_event_client,
             ret_value=None,
             method_name=None)
-        expected_msg = 'Timeout waiting for event "ha" .*'
+        expected_msg = 'Timed out after waiting .*s for event "ha" .*'
         with self.assertRaisesRegex(callback_handler.TimeoutError,
-                                     expected_msg):
+                                    expected_msg):
             handler.waitAndGet('ha')
 
     def test_wait_for_event(self):
@@ -101,7 +102,7 @@ class CallbackHandlerTest(unittest.TestCase):
             return False
 
         with self.assertRaisesRegex(callback_handler.TimeoutError,
-                                     expected_msg):
+                                    expected_msg):
             handler.waitForEvent('AsyncTaskResult', some_condition, 0.01)
 
 
diff --git a/tests/mobly/controllers/android_device_lib/snippet_client_test.py b/tests/mobly/controllers/android_device_lib/snippet_client_test.py
index 010064c..beb9262 100755
--- a/tests/mobly/controllers/android_device_lib/snippet_client_test.py
+++ b/tests/mobly/controllers/android_device_lib/snippet_client_test.py
@@ -18,6 +18,7 @@ from builtins import bytes
 import mock
 from future.tests.base import unittest
 
+from mobly.controllers.android_device_lib import adb
 from mobly.controllers.android_device_lib import jsonrpc_client_base
 from mobly.controllers.android_device_lib import snippet_client
 from tests.lib import jsonrpc_client_test_base
@@ -51,6 +52,8 @@ class MockAdbProxy(object):
             return bytes('instrumentation:{p}/{r} (target={p})'.format(
                 p=MOCK_PACKAGE_NAME,
                 r=snippet_client._INSTRUMENTATION_RUNNER_PACKAGE), 'utf-8')
+        elif 'which' in params:
+            return ''
 
     def __getattr__(self, name):
         """All calls to the none-existent functions in adb proxy would
@@ -175,6 +178,73 @@ class SnippetClientTest(jsonrpc_client_test_base.JsonRpcClientTestBase):
         client.start_app_and_connect()
         self.assertEqual(123, client.device_port)
 
+    @mock.patch('mobly.controllers.android_device_lib.snippet_client.'
+                'SnippetClient._do_start_app')
+    @mock.patch('mobly.controllers.android_device_lib.snippet_client.'
+                'SnippetClient._check_app_installed')
+    @mock.patch('mobly.controllers.android_device_lib.snippet_client.'
+                'SnippetClient._read_protocol_line')
+    @mock.patch('mobly.controllers.android_device_lib.snippet_client.'
+                'SnippetClient._connect_to_v1')
+    @mock.patch('mobly.controllers.android_device_lib.snippet_client.'
+                'utils.get_available_host_port')
+    def test_snippet_start_app_and_connect_v1_persistent_session(
+            self, mock_get_port, mock_connect_to_v1, mock_read_protocol_line,
+            mock_check_app_installed, mock_do_start_app):
+
+        def _mocked_shell(arg):
+            if 'setsid' in arg:
+                raise adb.AdbError('cmd', 'stdout', 'stderr', 'ret_code')
+            else:
+                return 'nohup'
+
+        mock_get_port.return_value = 123
+        mock_read_protocol_line.side_effect = [
+            'SNIPPET START, PROTOCOL 1 234',
+            'SNIPPET SERVING, PORT 1234',
+            'SNIPPET START, PROTOCOL 1 234',
+            'SNIPPET SERVING, PORT 1234',
+            'SNIPPET START, PROTOCOL 1 234',
+            'SNIPPET SERVING, PORT 1234',
+        ]
+
+        # Test 'setsid' exists
+        client = self._make_client()
+        client._adb.shell = mock.Mock(return_value='setsid')
+        client.start_app_and_connect()
+        cmd_setsid = '%s am instrument -w -e action start %s/%s' % (
+            snippet_client._SETSID_COMMAND,
+            MOCK_PACKAGE_NAME,
+            snippet_client._INSTRUMENTATION_RUNNER_PACKAGE)
+        mock_do_start_app.assert_has_calls(mock.call(cmd_setsid))
+
+        # Test 'setsid' does not exist, but 'nohup' exsits
+        client = self._make_client()
+        client._adb.shell = _mocked_shell
+        client.start_app_and_connect()
+        cmd_nohup = '%s am instrument -w -e action start %s/%s' % (
+            snippet_client._NOHUP_COMMAND,
+            MOCK_PACKAGE_NAME,
+            snippet_client._INSTRUMENTATION_RUNNER_PACKAGE)
+        mock_do_start_app.assert_has_calls([
+            mock.call(cmd_setsid),
+            mock.call(cmd_nohup)
+        ])
+
+        # Test both 'setsid' and 'nohup' do not exist
+        client._adb.shell = mock.Mock(
+            side_effect=adb.AdbError('cmd', 'stdout', 'stderr', 'ret_code'))
+        client = self._make_client()
+        client.start_app_and_connect()
+        cmd_not_persist = ' am instrument -w -e action start %s/%s' % (
+            MOCK_PACKAGE_NAME,
+            snippet_client._INSTRUMENTATION_RUNNER_PACKAGE)
+        mock_do_start_app.assert_has_calls([
+            mock.call(cmd_setsid),
+            mock.call(cmd_nohup),
+            mock.call(cmd_not_persist)
+        ])
+
     @mock.patch('socket.create_connection')
     @mock.patch('mobly.controllers.android_device_lib.snippet_client.'
                 'utils.start_standing_subprocess')