Repository: google/mobly

Issue:
`_execute_and_process_stdout` should log cmd

Discussion:
xpconanfan: I don't see how this is related to logging stderr as the issue described.
One of the msg is incorrect?

---

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

---

*[mobly/controllers/android_device_lib/adb.py, line 215 at r1](https://reviewable.io/reviews/google/mobly/453#-LDIjCGd2zhkKzp2ablH:-LDIjCGd2zhkKzp2ablI:b-x8c38) ([raw file](https://github.com/google/mobly/blob/73f94e45966ec8566eabae03fc00893e5a13ee33/mobly/controllers/android_device_lib/adb.py#L215)):*
> ```Python
>                     break
>         finally:
>             (unhandled_out, err) = proc.communicate()
> ```

wait, so this does happen?
shouldn't we call the handler with this out instead?

---


*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/453#-:-LDIjnBO4MUgZxYNImBt:blud5im)*
<!-- Sent from Reviewable.io -->

winterfroststrom: 



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

---

*[mobly/controllers/android_device_lib/adb.py, line 215 at r1](https://reviewable.io/reviews/google/mobly/453#-LDIjCGd2zhkKzp2ablH:-LDIkOBz8aQLOE0ovB8O:brjczjz) ([raw file](https://github.com/google/mobly/blob/73f94e45966ec8566eabae03fc00893e5a13ee33/mobly/controllers/android_device_lib/adb.py#L215)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

wait, so this does happen?
shouldn't we call the handler with this out instead?
</blockquote></details>

I'm not sure?
I'm adding logging here first to try to determine what the underlying problem is

---


*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/453)*
<!-- 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 215 at r1](https://reviewable.io/reviews/google/mobly/453#-LDIjCGd2zhkKzp2ablH:-LDIl2971UfZ3LqypsHv:b332s67) ([raw file](https://github.com/google/mobly/blob/73f94e45966ec8566eabae03fc00893e5a13ee33/mobly/controllers/android_device_lib/adb.py#L215)):*
<details><summary><i>Previously, winterfroststrom wrote…</i></summary><blockquote>

I'm not sure?
I'm adding logging here first to try to determine what the underlying problem is
</blockquote></details>

seems like we should pipe all stdout content through the handler as this function promised?
you could add additional logging to signify the existence of stdout from `communicate`?

---


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

xpconanfan: 



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

---

*[tests/mobly/controllers/android_device_lib/adb_test.py, line 156 at r1](https://reviewable.io/reviews/google/mobly/453#-LDImOOR-GL1gRhihxxl:-LDImOOR-GL1gRhihxxm:ba86vyn) ([raw file](https://github.com/google/mobly/blob/73f94e45966ec8566eabae03fc00893e5a13ee33/tests/mobly/controllers/android_device_lib/adb_test.py#L156)):*
> ```Python
>     def test_execute_and_process_stdout_logs_cmd(self, mock_debug_logger,
>                                                  mock_popen):
>         self._mock_execute_and_process_stdout_process(mock_popen)
> ```

this test is relying on the default mock stdout value in `_mock_execute_and_process_stdout_process`, which is difficult to read.
Can we more explicitly set the mock value within the test?

---


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

winterfroststrom: 



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

---

*[mobly/controllers/android_device_lib/adb.py, line 215 at r1](https://reviewable.io/reviews/google/mobly/453#-LDIjCGd2zhkKzp2ablH:-LDIsvuPD4jS9CVrpnr5:bcy1d3j) ([raw file](https://github.com/google/mobly/blob/73f94e45966ec8566eabae03fc00893e5a13ee33/mobly/controllers/android_device_lib/adb.py#L215)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

seems like we should pipe all stdout content through the handler as this function promised?
you could add additional logging to signify the existence of stdout from `communicate`?
</blockquote></details>

So, I've never seen this output actually get populated and I'm not sure it is in the case I'm debugging, but okay.

I'm preferring changing the logged command because otherwise you'd get semi-duplicate log lines.

---

*[tests/mobly/controllers/android_device_lib/adb_test.py, line 156 at r1](https://reviewable.io/reviews/google/mobly/453#-LDImOOR-GL1gRhihxxl:-LDItG5yEIdICTRzP1c0:b-896fix) ([raw file](https://github.com/google/mobly/blob/73f94e45966ec8566eabae03fc00893e5a13ee33/tests/mobly/controllers/android_device_lib/adb_test.py#L156)):*
<details><summary><i>Previously, xpconanfan (Ang Li) wrote…</i></summary><blockquote>

this test is relying on the default mock stdout value in `_mock_execute_and_process_stdout_process`, which is difficult to read.
Can we more explicitly set the mock value within the test?
</blockquote></details>

Done.

---


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

xpconanfan: <img class="emoji" title=":lgtm:" alt=":lgtm:" align="absmiddle" src="https://reviewable.io/lgtm.png" height="20" width="61"/>

---

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

---



*Comments from [Reviewable](https://reviewable.io/reviews/google/mobly/453#-:-LEBweyyBV-cQJiSKgM7:bnfp4nl)*
<!-- Sent from Reviewable.io -->


Patch:
diff --git a/mobly/controllers/android_device_lib/adb.py b/mobly/controllers/android_device_lib/adb.py
index 90dcd0b..95d1261 100644
--- a/mobly/controllers/android_device_lib/adb.py
+++ b/mobly/controllers/android_device_lib/adb.py
@@ -203,6 +203,7 @@ class AdbProxy(object):
             stderr=subprocess.PIPE,
             shell=shell,
             bufsize=1)
+        out = '[elided, processed via handler]'
         try:
             while proc.poll() is None:
                 line = proc.stdout.readline()
@@ -211,16 +212,19 @@ class AdbProxy(object):
                 else:
                     break
         finally:
-            (_, err) = proc.communicate()
+            (unexpected_out, err) = proc.communicate()
+            if unexpected_out:
+                out = '[unexpected stdout] %s' % unexpected_out
+                for line in unexpected_out.splitlines():
+                    handler(line)
+
         ret = proc.returncode
+        logging.debug('cmd: %s, stdout: %s, stderr: %s, ret: %s',
+                      cli_cmd_to_string(args), out, err, ret)
         if ret == 0:
             return err
         else:
-            raise AdbError(
-                cmd=args,
-                stdout='[elided, processed via handler]',
-                stderr=err,
-                ret_code=ret)
+            raise AdbError(cmd=args, stdout=out, stderr=err, ret_code=ret)
 
     def _construct_adb_cmd(self, raw_name, args, shell):
         """Constructs an adb command with arguments for a subprocess call.
diff --git a/mobly/controllers/android_device_lib/snippet_client.py b/mobly/controllers/android_device_lib/snippet_client.py
index e3e835d..03674ff 100644
--- a/mobly/controllers/android_device_lib/snippet_client.py
+++ b/mobly/controllers/android_device_lib/snippet_client.py
@@ -125,8 +125,7 @@ class SnippetClient(jsonrpc_client_base.JsonRpcClientBase):
 
         # Yaaay! We're done!
         self.log.debug('Snippet %s started after %.1fs on host port %s',
-                       self.package,
-                       time.time() - start_time, self.host_port)
+                       self.package, time.time() - start_time, self.host_port)
 
     def restore_app_connection(self, port=None):
         """Restores the app after device got reconnected.
@@ -151,12 +150,13 @@ class SnippetClient(jsonrpc_client_base.JsonRpcClientBase):
         try:
             self.connect()
         except:
-            # Failed to connect to app, something went wrong.
+            # Log the original error and raise AppRestoreConnectionError.
+            self.log.exception('Failed to re-connect to app.')
             raise jsonrpc_client_base.AppRestoreConnectionError(
-                self._ad(
-                    'Failed to restore app connection for %s at host port %s, '
-                    'device port %s'), self.package, self.host_port,
-                self.device_port)
+                self._ad,
+                ('Failed to restore app connection for %s at host port %s, '
+                 'device port %s') % (self.package, self.host_port,
+                                      self.device_port))
 
         # Because the previous connection was lost, update self._proc
         self._proc = None


Test patch:
diff --git a/tests/mobly/controllers/android_device_lib/adb_test.py b/tests/mobly/controllers/android_device_lib/adb_test.py
index 1c75a9d..8dec8aa 100755
--- a/tests/mobly/controllers/android_device_lib/adb_test.py
+++ b/tests/mobly/controllers/android_device_lib/adb_test.py
@@ -76,8 +76,7 @@ class AdbTest(unittest.TestCase):
         mock_popen.return_value.stdout.readline.side_effect = ['']
 
         mock_proc.communicate = mock.Mock(
-            return_value=(MOCK_DEFAULT_STDOUT.encode('utf-8'),
-                          MOCK_DEFAULT_STDERR.encode('utf-8')))
+            return_value=('', MOCK_DEFAULT_STDERR.encode('utf-8')))
         mock_proc.returncode = 0
         return mock_popen
 
@@ -150,6 +149,57 @@ class AdbTest(unittest.TestCase):
         mock_handler.assert_any_call('1')
         mock_handler.assert_any_call('2')
 
+    @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
+    def test_execute_and_process_stdout_reads_unexpected_stdout(
+            self, mock_popen):
+        unexpected_stdout = MOCK_DEFAULT_STDOUT.encode('utf-8')
+
+        self._mock_execute_and_process_stdout_process(mock_popen)
+        mock_handler = mock.MagicMock()
+        mock_popen.return_value.communicate = mock.Mock(
+            return_value=(unexpected_stdout, MOCK_DEFAULT_STDERR.encode(
+                'utf-8')))
+
+        err = adb.AdbProxy()._execute_and_process_stdout(
+            ['fake_cmd'], shell=False, handler=mock_handler)
+        self.assertEqual(mock_handler.call_count, 1)
+        mock_handler.assert_called_with(unexpected_stdout)
+
+    @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
+    @mock.patch('logging.debug')
+    def test_execute_and_process_stdout_logs_cmd(self, mock_debug_logger,
+                                                 mock_popen):
+        raw_expected_stdout = ''
+        expected_stdout = '[elided, processed via handler]'
+        expected_stderr = MOCK_DEFAULT_STDERR.encode('utf-8')
+        self._mock_execute_and_process_stdout_process(mock_popen)
+        mock_popen.return_value.communicate = mock.Mock(
+            return_value=(raw_expected_stdout, expected_stderr))
+
+        err = adb.AdbProxy()._execute_and_process_stdout(
+            ['fake_cmd'], shell=False, handler=mock.MagicMock())
+        mock_debug_logger.assert_called_with(
+            'cmd: %s, stdout: %s, stderr: %s, ret: %s', 'fake_cmd',
+            expected_stdout, expected_stderr, 0)
+
+    @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
+    @mock.patch('logging.debug')
+    def test_execute_and_process_stdout_logs_cmd_with_unexpected_stdout(
+            self, mock_debug_logger, mock_popen):
+        raw_expected_stdout = MOCK_DEFAULT_STDOUT.encode('utf-8')
+        expected_stdout = '[unexpected stdout] %s' % raw_expected_stdout
+        expected_stderr = MOCK_DEFAULT_STDERR.encode('utf-8')
+
+        self._mock_execute_and_process_stdout_process(mock_popen)
+        mock_popen.return_value.communicate = mock.Mock(
+            return_value=(raw_expected_stdout, expected_stderr))
+
+        err = adb.AdbProxy()._execute_and_process_stdout(
+            ['fake_cmd'], shell=False, handler=mock.MagicMock())
+        mock_debug_logger.assert_called_with(
+            'cmd: %s, stdout: %s, stderr: %s, ret: %s', 'fake_cmd',
+            expected_stdout, expected_stderr, 0)
+
     @mock.patch('mobly.controllers.android_device_lib.adb.subprocess.Popen')
     def test_execute_and_process_stdout_when_cmd_exits(self, mock_popen):
         self._mock_execute_and_process_stdout_process(mock_popen)
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 2c875d8..d964ae3 100755
--- a/tests/mobly/controllers/android_device_lib/snippet_client_test.py
+++ b/tests/mobly/controllers/android_device_lib/snippet_client_test.py
@@ -166,6 +166,15 @@ class SnippetClientTest(jsonrpc_client_test_base.JsonRpcClientTestBase):
         self.assertEqual(789, callback._event_client.host_port)
         self.assertEqual(456, callback._event_client.device_port)
 
+        # if unable to reconnect for any reason, a
+        # jsonrpc_client_base.AppRestoreConnectionError is raised.
+        mock_create_connection.side_effect = IOError('socket timed out')
+        with self.assertRaisesRegex(
+                jsonrpc_client_base.AppRestoreConnectionError,
+            ('Failed to restore app connection for %s at host port %s, '
+             'device port %s') % (MOCK_PACKAGE_NAME, 789, 456)):
+            client.restore_app_connection()
+
     @mock.patch('socket.create_connection')
     @mock.patch('mobly.controllers.android_device_lib.snippet_client.'
                 'utils.start_standing_subprocess')