Truncate and sanitize stdout/stderr logs in adb_controller on command failure/timeout to prevent log spam and hangs when commands return large binary outputs.

android_env/components/adb_controller.py

@@ -48,7 +48,7 @@ def __init__(self, config: config_classes.AdbControllerConfig):
     self._os_env_vars.update(
         {'HOME': os.path.expandvars(self._os_env_vars.get('HOME', ''))}
     )
-    logging.info('self._os_env_vars: %r', self._os_env_vars)
+    # logging.info('self._os_env_vars: %r', self._os_env_vars)
 
   def command_prefix(self, include_device_name: bool = True) -> list[str]:
     """The command for instantiating an adb client to this server."""
@@ -128,7 +128,7 @@ def execute_command(
     latest_error = None
     for i in range(n_tries):
       try:
-        logging.info('Executing ADB command: [%s]', command_str)
+        # logging.info('Executing ADB command: [%s]', command_str)
         cmd_output = subprocess.check_output(
             command,
             stderr=subprocess.STDOUT,
@@ -145,13 +145,31 @@ def execute_command(
             command_str,
         )
         if e.stdout is not None:
-          logging.error('**stdout**:')
-          for line in e.stdout.splitlines():
-            logging.error('    %s', line)
+          logging.error('**stdout** (truncated):')
+          stdout_lines = e.stdout.splitlines()
+          for line in stdout_lines[:10]:
+            if any(b < 32 or b > 126 for b in line if b not in (9, 10, 13)):
+              logging.error('    [binary data, size %d]', len(line))
+              break
+            else:
+              logging.error(
+                  '    %s', line[:200].decode('utf-8', errors='replace')
+              )
+          if len(stdout_lines) > 10:
+            logging.error('    ... and %d more lines', len(stdout_lines) - 10)
         if e.stderr is not None:
-          logging.error('**stderr**:')
-          for line in e.stderr.splitlines():
-            logging.error('    %s', line)
+          logging.error('**stderr** (truncated):')
+          stderr_lines = e.stderr.splitlines()
+          for line in stderr_lines[:10]:
+            if any(b < 32 or b > 126 for b in line if b not in (9, 10, 13)):
+              logging.error('    [binary data, size %d]', len(line))
+              break
+            else:
+              logging.error(
+                  '    %s', line[:200].decode('utf-8', errors='replace')
+              )
+          if len(stderr_lines) > 10:
+            logging.error('    ... and %d more lines', len(stderr_lines) - 10)
         latest_error = e
         if device_specific and i < n_tries - 1:
           self._restart_server(timeout=timeout)

android_env/components/adb_controller_test.py

@@ -260,6 +260,98 @@ def test_avoid_infinite_recursion(self, mock_sleep, mock_check_output):
         timeout=_TIMEOUT,
     )
 
+  @mock.patch.object(subprocess, 'check_output', autospec=True)
+  @mock.patch.object(time, 'sleep', autospec=True)
+  @mock.patch.object(adb_controller_lib.logging, 'error', autospec=True)
+  @mock.patch.object(adb_controller_lib.logging, 'exception', autospec=True)
+  def test_timeout_binary_logging(
+      self,
+      mock_logging_exception,
+      mock_logging_error,
+      mock_sleep,
+      mock_check_output,
+  ):
+    """Verify that binary output from timed out command is truncated in logs."""
+    del mock_sleep, mock_logging_exception
+
+    binary_line = b'\x00\x01\x02\x03\x0a'
+    huge_binary_output = binary_line * 1000
+    mock_check_output.side_effect = subprocess.TimeoutExpired(
+        cmd='screencap', timeout=120.0, output=huge_binary_output
+    )
+
+    adb_controller = adb_controller_lib.AdbController(
+        config_classes.AdbControllerConfig(
+            adb_path='my_adb',
+            device_name='awesome_device',
+            use_adb_server_port_from_os_env=True,
+        )
+    )
+
+    with self.assertRaises(errors.AdbControllerError):
+      # Pass device_specific=False to avoid server restarts, but it still tries 2 times.
+      adb_controller.execute_command(
+          ['version'], timeout=_TIMEOUT, device_specific=False
+      )
+
+    error_calls = mock_logging_error.call_args_list
+    self.assertLen(error_calls, 6)  # 2 tries * 3 logs per try
+    self.assertEqual(error_calls[0], mock.call('**stdout** (truncated):'))
+    self.assertEqual(error_calls[1], mock.call('    [binary data, size %d]', 4))
+    self.assertEqual(
+        error_calls[2], mock.call('    ... and %d more lines', 990)
+    )
+    self.assertEqual(error_calls[3], mock.call('**stdout** (truncated):'))
+    self.assertEqual(error_calls[4], mock.call('    [binary data, size %d]', 4))
+    self.assertEqual(
+        error_calls[5], mock.call('    ... and %d more lines', 990)
+    )
+
+  @mock.patch.object(subprocess, 'check_output', autospec=True)
+  @mock.patch.object(time, 'sleep', autospec=True)
+  @mock.patch.object(adb_controller_lib.logging, 'error', autospec=True)
+  @mock.patch.object(adb_controller_lib.logging, 'exception', autospec=True)
+  def test_timeout_long_text_logging(
+      self,
+      mock_logging_exception,
+      mock_logging_error,
+      mock_sleep,
+      mock_check_output,
+  ):
+    """Verify that long text output from timed out command is truncated in logs."""
+    del mock_sleep, mock_logging_exception
+
+    text_output = b'line\n' * 20
+    mock_check_output.side_effect = subprocess.TimeoutExpired(
+        cmd='blah', timeout=120.0, output=text_output
+    )
+
+    adb_controller = adb_controller_lib.AdbController(
+        config_classes.AdbControllerConfig(
+            adb_path='my_adb',
+            device_name='awesome_device',
+            use_adb_server_port_from_os_env=True,
+        )
+    )
+
+    with self.assertRaises(errors.AdbControllerError):
+      # Pass device_specific=False to avoid server restarts, but it still tries 2 times.
+      adb_controller.execute_command(
+          ['version'], timeout=_TIMEOUT, device_specific=False
+      )
+
+    error_calls = mock_logging_error.call_args_list
+    self.assertLen(error_calls, 24)  # 2 tries * 12 logs per try
+    for offset in (0, 12):
+      self.assertEqual(
+          error_calls[offset], mock.call('**stdout** (truncated):')
+      )
+      for i in range(1, 11):
+        self.assertEqual(error_calls[offset + i], mock.call('    %s', 'line'))
+      self.assertEqual(
+          error_calls[offset + 11], mock.call('    ... and %d more lines', 10)
+      )
+
 
 class AdbControllerInitTest(absltest.TestCase):