Repository: google/mobly

Issue:
Propagate stderr from adb commands
The current mobly adb proxy does not propagate stderr if ret code is zero.
We thought this was ok since Android has fixed return code issues in M.

But turns out many China manufacturers did not fix this in China devices.
In order to better support China devices and potentially other devices of the same ret code problem, we need to surface stderr.

Discussion:
dthkao: 



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

---

*[mobly/controllers/android_device_lib/adb.py, line 279 at r1](https://beta.reviewable.io/reviews/google/mobly/437#-LAIsFf7-05sU6C6Hx5K:-LAIsFf7-05sU6C6Hx5L:b1zt8o6) ([raw file](https://github.com/google/mobly/blob/93853c8ba9cc06560e500141a68f3fa9039824ab/mobly/controllers/android_device_lib/adb.py#L279)):*
> ```Python
> 
>     def __getattr__(self, name):
>         def adb_call(args=None, shell=False, timeout=None, return_all=False):
> ```

I'm not a huge fan of signatures changing based on a flag. Is there a way we can make this an init-level setting instead of per-call?

---


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

xpconanfan: 



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

---

*[mobly/controllers/android_device_lib/adb.py, line 279 at r1](https://beta.reviewable.io/reviews/google/mobly/437#-LAIsFf7-05sU6C6Hx5K:-LAIv4JN3Pnm3xAhzfbd:bwk8scm) ([raw file](https://github.com/google/mobly/blob/93853c8ba9cc06560e500141a68f3fa9039824ab/mobly/controllers/android_device_lib/adb.py#L279)):*
<details><summary><i>Previously, dthkao (David T.H. Kao) wrote…</i></summary><blockquote>

I'm not a huge fan of signatures changing based on a flag. Is there a way we can make this an init-level setting instead of per-call?
</blockquote></details>

I thought of the same thing initially.
However that wouldn't work since that'll break any util that makes adb calls and expect a single output, which is quite a lot.

---


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


Patch:
diff --git a/mobly/controllers/android_device_lib/adb.py b/mobly/controllers/android_device_lib/adb.py
index 432f08e..12c14bd 100644
--- a/mobly/controllers/android_device_lib/adb.py
+++ b/mobly/controllers/android_device_lib/adb.py
@@ -138,7 +138,7 @@ class AdbProxy(object):
     def __init__(self, serial=''):
         self.serial = serial
 
-    def _exec_cmd(self, args, shell, timeout):
+    def _exec_cmd(self, args, shell, timeout, stderr):
         """Executes adb commands.
 
         Args:
@@ -148,6 +148,8 @@ class AdbProxy(object):
                 False to invoke it directly. See subprocess.Popen() docs.
             timeout: float, the number of seconds to wait before timing out.
                 If not specified, no timeout takes effect.
+            stderr: a Byte stream, like io.BytesIO, stderr of the command will
+                be written to this object if provided.
 
         Returns:
             The output of the adb command run if exit code is 0.
@@ -169,6 +171,8 @@ class AdbProxy(object):
                 raise AdbTimeoutError(cmd=args, timeout=timeout)
 
         (out, err) = proc.communicate()
+        if stderr:
+            stderr.write(err)
         ret = proc.returncode
         logging.debug('cmd: %s, stdout: %s, stderr: %s, ret: %s',
                       cli_cmd_to_string(args), out, err, ret)
@@ -177,7 +181,7 @@ class AdbProxy(object):
         else:
             raise AdbError(cmd=args, stdout=out, stderr=err, ret_code=ret)
 
-    def _exec_adb_cmd(self, name, args, shell, timeout):
+    def _exec_adb_cmd(self, name, args, shell, timeout, stderr):
         if shell:
             # Add quotes around "adb" in case the ADB path contains spaces. This
             # is pretty common on Windows (e.g. Program Files).
@@ -195,7 +199,9 @@ class AdbProxy(object):
                     adb_cmd.append(args)
                 else:
                     adb_cmd.extend(args)
-        return self._exec_cmd(adb_cmd, shell=shell, timeout=timeout)
+        out = self._exec_cmd(
+            adb_cmd, shell=shell, timeout=timeout, stderr=stderr)
+        return out
 
     def getprop(self, prop_name):
         """Get a property of the device.
@@ -273,7 +279,7 @@ class AdbProxy(object):
         return self.shell(instrumentation_command)
 
     def __getattr__(self, name):
-        def adb_call(args=None, shell=False, timeout=None):
+        def adb_call(args=None, shell=False, timeout=None, stderr=None):
             """Wrapper for an ADB command.
 
             Args:
@@ -283,6 +289,8 @@ class AdbProxy(object):
                     False to invoke it directly. See subprocess.Proc() docs.
                 timeout: float, the number of seconds to wait before timing out.
                     If not specified, no timeout takes effect.
+                stderr: a Byte stream, like io.BytesIO, stderr of the command
+                    will be written to this object if provided.
 
             Returns:
                 The output of the adb command run if exit code is 0.
@@ -290,6 +298,6 @@ class AdbProxy(object):
             args = args or ''
             clean_name = name.replace('_', '-')
             return self._exec_adb_cmd(
-                clean_name, args, shell=shell, timeout=timeout)
+                clean_name, args, shell=shell, timeout=timeout, stderr=stderr)
 
         return adb_call


Test patch:
diff --git a/mobly/base_instrumentation_test.py b/mobly/base_instrumentation_test.py
index 4966cd4..bb72075 100644
--- a/mobly/base_instrumentation_test.py
+++ b/mobly/base_instrumentation_test.py
@@ -927,7 +927,7 @@ class BaseInstrumentationTestClass(base_test.BaseTestClass):
             package=package,
             options=options,
             runner=runner,
-        )
+        ).decode('utf-8')
         logging.info('Outputting instrumentation test log...')
         logging.info(instrumentation_output)
 
@@ -935,5 +935,5 @@ class BaseInstrumentationTestClass(base_test.BaseTestClass):
         instrumentation_block = _InstrumentationBlock(prefix=prefix)
         for line in instrumentation_output.splitlines():
             instrumentation_block = self._parse_line(instrumentation_block,
-                                                     line.decode('utf-8'))
+                                                     line)
         return self._finish_parsing(instrumentation_block)
diff --git a/mobly/base_test.py b/mobly/base_test.py
index 8b761fa..e4e047b 100644
--- a/mobly/base_test.py
+++ b/mobly/base_test.py
@@ -26,6 +26,7 @@ from mobly import expects
 from mobly import records
 from mobly import signals
 from mobly import runtime_test_info
+from mobly import utils
 
 # Macro strings for test result reporting
 TEST_CASE_TOKEN = '[Test]'
@@ -351,7 +352,7 @@ class BaseTestClass(object):
             content: dict, the data to add to summary file.
         """
         if 'timestamp' not in content:
-            content['timestamp'] = time.time()
+            content['timestamp'] = utils.get_current_epoch_time()
         self.summary_writer.dump(content,
                                  records.TestSummaryEntryType.USER_DATA)
 
diff --git a/tests/mobly/base_instrumentation_test_test.py b/tests/mobly/base_instrumentation_test_test.py
index 2256475..3908015 100755
--- a/tests/mobly/base_instrumentation_test_test.py
+++ b/tests/mobly/base_instrumentation_test_test.py
@@ -34,6 +34,17 @@ MOCK_PREFIX = 'my_prefix'
 # A mock name for the instrumentation test subclass.
 MOCK_INSTRUMENTATION_TEST_CLASS_NAME = 'MockInstrumentationTest'
 
+MOCK_EMPTY_INSTRUMENTATION_TEST = """\
+INSTRUMENTATION_RESULT: stream=
+
+Time: 0.001
+
+OK (0 tests)
+
+
+INSTRUMENTATION_CODE: -1
+"""
+
 
 class MockInstrumentationTest(BaseInstrumentationTestClass):
     def __init__(self, tmp_dir, user_params={}):
@@ -229,18 +240,21 @@ INSTRUMENTATION_STATUS_CODE: -1
             instrumentation_output, expected_has_error=True)
 
     def test_run_instrumentation_test_with_no_tests(self):
-        instrumentation_output = """\
-INSTRUMENTATION_RESULT: stream=
-
-Time: 0.001
-
-OK (0 tests)
-
+        instrumentation_output = MOCK_EMPTY_INSTRUMENTATION_TEST
+        self.assert_run_instrumentation_test(
+            instrumentation_output, expected_completed_and_passed=True)
 
-INSTRUMENTATION_CODE: -1
-"""
+    @unittest.skipUnless(
+        sys.version_info >= (3, 0),
+        'Only python3 displays different string types differently.')
+    @mock.patch('logging.info')
+    def test_run_instrumentation_test_logs_correctly(self, mock_info_logger):
+        instrumentation_output = MOCK_EMPTY_INSTRUMENTATION_TEST
         self.assert_run_instrumentation_test(
             instrumentation_output, expected_completed_and_passed=True)
+        for mock_call in mock_info_logger.mock_calls:
+            logged_format = mock_call[1][0]
+            self.assertIsInstance(logged_format, str)
 
     def test_run_instrumentation_test_with_passing_test(self):
         instrumentation_output = """\
diff --git a/tests/mobly/controllers/android_device_lib/adb_test.py b/tests/mobly/controllers/android_device_lib/adb_test.py
index 9eb3ab8..7bf61ab 100755
--- a/tests/mobly/controllers/android_device_lib/adb_test.py
+++ b/tests/mobly/controllers/android_device_lib/adb_test.py
@@ -12,11 +12,12 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+import io
 import mock
+import subprocess
 
 from collections import OrderedDict
 from future.tests.base import unittest
-
 from mobly.controllers.android_device_lib import adb
 
 # Mock parameters for instrumentation.
@@ -42,6 +43,9 @@ MOCK_OPTIONS_INSTRUMENTATION_COMMAND = ('am instrument -r -w -e option1 value1'
 # Mock Shell Command
 MOCK_SHELL_COMMAND = 'ls'
 MOCK_COMMAND_OUTPUT = '/system/bin/ls'.encode('utf-8')
+MOCK_DEFAULT_STDOUT = 'out'
+MOCK_DEFAULT_STDERR = 'err'
+MOCK_DEFAULT_COMMAND_OUTPUT = MOCK_DEFAULT_STDOUT.encode('utf-8')
 MOCK_ADB_SHELL_COMMAND_CHECK = 'adb shell command -v ls'
 
 
@@ -58,7 +62,8 @@ class AdbTest(unittest.TestCase):
         mock_psutil_process.return_value = mock.Mock()
 
         mock_proc.communicate = mock.Mock(
-            return_value=('out'.encode('utf-8'), 'err'.encode('utf-8')))
+            return_value=(MOCK_DEFAULT_STDOUT.encode('utf-8'),
+                          MOCK_DEFAULT_STDERR.encode('utf-8')))
         mock_proc.returncode = 0
         return (mock_psutil_process, mock_popen)
 
@@ -68,9 +73,9 @@ class AdbTest(unittest.TestCase):
                                          mock_Popen):
         self._mock_process(mock_psutil_process, mock_Popen)
 
-        reply = adb.AdbProxy()._exec_cmd(
-            ['fake_cmd'], shell=False, timeout=None)
-        self.assertEqual('out', reply.decode('utf-8'))
+        out = adb.AdbProxy()._exec_cmd(
+            ['fake_cmd'], shell=False, timeout=None, stderr=None)
+        self.assertEqual(MOCK_DEFAULT_STDOUT, out.decode('utf-8'))
 
     @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
     @mock.patch('mobly.controllers.android_device_lib.adb.psutil.Process')
@@ -81,7 +86,8 @@ class AdbTest(unittest.TestCase):
 
         with self.assertRaisesRegex(adb.AdbError,
                                     'Error executing adb cmd .*'):
-            adb.AdbProxy()._exec_cmd(['fake_cmd'], shell=False, timeout=None)
+            adb.AdbProxy()._exec_cmd(
+                ['fake_cmd'], shell=False, timeout=None, stderr=None)
 
     @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
     @mock.patch('mobly.controllers.android_device_lib.adb.psutil.Process')
@@ -89,8 +95,9 @@ class AdbTest(unittest.TestCase):
                                            mock_popen):
         self._mock_process(mock_psutil_process, mock_popen)
 
-        reply = adb.AdbProxy()._exec_cmd(['fake_cmd'], shell=False, timeout=1)
-        self.assertEqual('out', reply.decode('utf-8'))
+        out = adb.AdbProxy()._exec_cmd(
+            ['fake_cmd'], shell=False, timeout=1, stderr=None)
+        self.assertEqual(MOCK_DEFAULT_STDOUT, out.decode('utf-8'))
 
     @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
     @mock.patch('mobly.controllers.android_device_lib.adb.psutil.Process')
@@ -104,7 +111,8 @@ class AdbTest(unittest.TestCase):
         with self.assertRaisesRegex(adb.AdbTimeoutError,
                                     'Timed out executing command "fake_cmd" '
                                     'after 0.1s.'):
-            adb.AdbProxy()._exec_cmd(['fake_cmd'], shell=False, timeout=0.1)
+            adb.AdbProxy()._exec_cmd(
+                ['fake_cmd'], shell=False, timeout=0.1, stderr=None)
 
     @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
     @mock.patch('mobly.controllers.android_device_lib.adb.psutil.Process')
@@ -113,66 +121,100 @@ class AdbTest(unittest.TestCase):
         self._mock_process(mock_psutil_process, mock_popen)
         with self.assertRaisesRegex(adb.Error,
                                     'Timeout is not a positive value: -1'):
-            adb.AdbProxy()._exec_cmd(['fake_cmd'], shell=False, timeout=-1)
+            adb.AdbProxy()._exec_cmd(
+                ['fake_cmd'], shell=False, timeout=-1, stderr=None)
 
     def test_exec_adb_cmd(self):
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
+            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             adb.AdbProxy().shell(['arg1', 'arg2'])
             mock_exec_cmd.assert_called_once_with(
-                ['adb', 'shell', 'arg1', 'arg2'], shell=False, timeout=None)
+                ['adb', 'shell', 'arg1', 'arg2'],
+                shell=False,
+                timeout=None,
+                stderr=None)
+
+    def test_exec_adb_cmd_with_serial(self):
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
+            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             adb.AdbProxy('12345').shell(['arg1', 'arg2'])
             mock_exec_cmd.assert_called_once_with(
                 ['adb', '-s', '12345', 'shell', 'arg1', 'arg2'],
                 shell=False,
-                timeout=None)
+                timeout=None,
+                stderr=None)
 
     def test_exec_adb_cmd_with_shell_true(self):
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
+            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             adb.AdbProxy().shell('arg1 arg2', shell=True)
             mock_exec_cmd.assert_called_once_with(
-                '"adb" shell arg1 arg2', shell=True, timeout=None)
+                '"adb" shell arg1 arg2', shell=True, timeout=None, stderr=None)
+
+    def test_exec_adb_cmd_with_shell_true_with_serial(self):
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
+            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             adb.AdbProxy('12345').shell('arg1 arg2', shell=True)
             mock_exec_cmd.assert_called_once_with(
-                '"adb" -s "12345" shell arg1 arg2', shell=True, timeout=None)
+                '"adb" -s "12345" shell arg1 arg2',
+                shell=True,
+                timeout=None,
+                stderr=None)
+
+    @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
+    @mock.patch('mobly.controllers.android_device_lib.adb.psutil.Process')
+    def test_exec_adb_cmd_with_stderr_pipe(self, mock_psutil_process,
+                                           mock_popen):
+        self._mock_process(mock_psutil_process, mock_popen)
+        stderr_redirect = io.BytesIO()
+        out = adb.AdbProxy().shell(
+            'arg1 arg2', shell=True, stderr=stderr_redirect)
+        self.assertEqual(MOCK_DEFAULT_STDOUT, out.decode('utf-8'))
+        self.assertEqual(MOCK_DEFAULT_STDERR,
+                         stderr_redirect.getvalue().decode('utf-8'))
 
     def test_instrument_without_parameters(self):
         """Verifies the AndroidDevice object's instrument command is correct in
         the basic case.
         """
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
+            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             adb.AdbProxy().instrument(MOCK_INSTRUMENTATION_PACKAGE)
             mock_exec_cmd.assert_called_once_with(
                 ['adb', 'shell', MOCK_BASIC_INSTRUMENTATION_COMMAND],
                 shell=False,
-                timeout=None)
+                timeout=None,
+                stderr=None)
 
     def test_instrument_with_runner(self):
         """Verifies the AndroidDevice object's instrument command is correct
         with a runner specified.
         """
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
+            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             adb.AdbProxy().instrument(
                 MOCK_INSTRUMENTATION_PACKAGE,
                 runner=MOCK_INSTRUMENTATION_RUNNER)
             mock_exec_cmd.assert_called_once_with(
                 ['adb', 'shell', MOCK_RUNNER_INSTRUMENTATION_COMMAND],
                 shell=False,
-                timeout=None)
+                timeout=None,
+                stderr=None)
 
     def test_instrument_with_options(self):
         """Verifies the AndroidDevice object's instrument command is correct
         with options.
         """
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
+            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             adb.AdbProxy().instrument(
                 MOCK_INSTRUMENTATION_PACKAGE,
                 options=MOCK_INSTRUMENTATION_OPTIONS)
             mock_exec_cmd.assert_called_once_with(
                 ['adb', 'shell', MOCK_OPTIONS_INSTRUMENTATION_COMMAND],
                 shell=False,
-                timeout=None)
+                timeout=None,
+                stderr=None)
 
     def test_cli_cmd_to_string(self):
         cmd = ['"adb"', 'a b', 'c//']
@@ -182,11 +224,13 @@ class AdbTest(unittest.TestCase):
 
     def test_has_shell_command_called_correctly(self):
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
+            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             adb.AdbProxy().has_shell_command(MOCK_SHELL_COMMAND)
             mock_exec_cmd.assert_called_once_with(
                 ['adb', 'shell', 'command', '-v', MOCK_SHELL_COMMAND],
                 shell=False,
-                timeout=None)
+                timeout=None,
+                stderr=None)
 
     def test_has_shell_command_with_existing_command(self):
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
@@ -196,6 +240,7 @@ class AdbTest(unittest.TestCase):
 
     def test_has_shell_command_with_missing_command_on_older_devices(self):
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
+            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             mock_exec_cmd.side_effect = adb.AdbError(
                 MOCK_ADB_SHELL_COMMAND_CHECK, '', '', 0)
             self.assertFalse(
@@ -203,6 +248,7 @@ class AdbTest(unittest.TestCase):
 
     def test_has_shell_command_with_missing_command_on_newer_devices(self):
         with mock.patch.object(adb.AdbProxy, '_exec_cmd') as mock_exec_cmd:
+            mock_exec_cmd.return_value = MOCK_DEFAULT_COMMAND_OUTPUT
             mock_exec_cmd.side_effect = adb.AdbError(
                 MOCK_ADB_SHELL_COMMAND_CHECK, '', '', 1)
             self.assertFalse(