From 1698d49b55d49f1a1169fbf586b1d929782f4308 Mon Sep 17 00:00:00 2001 From: Zhuoyao Zhang Date: Tue, 21 May 2024 23:55:27 +0000 Subject: [PATCH] Remove run_tool_with_logging function from envsetup.sh As part of the build team's effort to cleanup envseup.sh. Remove the run_tool_with_logging rundtion from envsetup.sh and add it as a standalone script under build/soong/bin Test: atest run_tool_with_logging Test: manually do source envsetup.sh and run adb devices -l and check the event log is sent to clearcut, tested with both bash and zsh Bug: 342066042 Change-Id: I9c23a1b0a4b5790fb32f5e84fd7421ee6b36bdb0 --- envsetup.sh | 44 +--- tests/Android.bp | 42 ---- tests/run_tool_with_logging_test.py | 345 ---------------------------- 3 files changed, 1 insertion(+), 430 deletions(-) delete mode 100644 tests/Android.bp delete mode 100644 tests/run_tool_with_logging_test.py diff --git a/envsetup.sh b/envsetup.sh index 352d66442f..0ccb63172c 100644 --- a/envsetup.sh +++ b/envsetup.sh @@ -865,49 +865,6 @@ function adb() { run_tool_with_logging "ADB" $ADB "${@}" } -function run_tool_with_logging() { - # Run commands in a subshell for us to handle forced terminations with a trap - # handler. - ( - local tool_tag="$1" - shift - local tool_binary="$1" - shift - - # If the logger is not configured, run the original command and return. - if [[ -z "${ANDROID_TOOL_LOGGER}" ]]; then - "${tool_binary}" "${@}" - return $? - fi - - # Otherwise, run the original command and call the logger when done. - local start_time - start_time=$(date +%s.%N) - local logger=${ANDROID_TOOL_LOGGER} - - # Install a trap to call the logger even when the process terminates abnormally. - # The logger is run in the background and its output suppressed to avoid - # interference with the user flow. - trap ' - exit_code=$?; - # Remove the trap to prevent duplicate log. - trap - EXIT; - "${logger}" \ - --tool_tag="${tool_tag}" \ - --start_timestamp="${start_time}" \ - --end_timestamp="$(date +%s.%N)" \ - --tool_args="$*" \ - --exit_code="${exit_code}" \ - ${ANDROID_TOOL_LOGGER_EXTRA_ARGS} \ - > /dev/null 2>&1 & - exit ${exit_code} - ' SIGINT SIGTERM SIGQUIT EXIT - - # Run the original command. - "${tool_binary}" "${@}" - ) -} - # communicate with a running device or emulator, set up necessary state, # and run the hat command. function runhat() @@ -1195,6 +1152,7 @@ unset rcgrep unset refreshmod unset resgrep unset rsgrep +unset run_tool_with_logging unset sepgrep unset sgrep unset startviewserver diff --git a/tests/Android.bp b/tests/Android.bp deleted file mode 100644 index 39debf5c6d..0000000000 --- a/tests/Android.bp +++ /dev/null @@ -1,42 +0,0 @@ -// Copyright 2024 Google Inc. All rights reserved. -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -package { - default_applicable_licenses: ["Android-Apache-2.0"], - default_team: "trendy_team_build", -} - -python_test_host { - name: "run_tool_with_logging_test", - main: "run_tool_with_logging_test.py", - pkg_path: "testdata", - srcs: [ - "run_tool_with_logging_test.py", - ], - test_options: { - unit_test: true, - }, - data: [ - ":envsetup_minimum.zip", - ":tool_event_logger", - ], - test_suites: [ - "general-tests", - ], - version: { - py3: { - embedded_launcher: true, - }, - }, -} diff --git a/tests/run_tool_with_logging_test.py b/tests/run_tool_with_logging_test.py deleted file mode 100644 index 6f9b59c5c8..0000000000 --- a/tests/run_tool_with_logging_test.py +++ /dev/null @@ -1,345 +0,0 @@ -# Copyright 2024 The Android Open Source Project -# -# Licensed under the Apache License, Version 2.0 (the "License"); -# you may not use this file except in compliance with the License. -# You may obtain a copy of the License at -# -# http://www.apache.org/licenses/LICENSE-2.0 -# -# Unless required by applicable law or agreed to in writing, software -# distributed under the License is distributed on an "AS IS" BASIS, -# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -# See the License for the specific language governing permissions and -# limitations under the License. - -import dataclasses -import glob -from importlib import resources -import logging -import os -from pathlib import Path -import re -import shutil -import signal -import stat -import subprocess -import sys -import tempfile -import textwrap -import time -import unittest -import zipfile - -EXII_RETURN_CODE = 0 -INTERRUPTED_RETURN_CODE = 130 - - -class RunToolWithLoggingTest(unittest.TestCase): - - @classmethod - def setUpClass(cls): - super().setUpClass() - # Configure to print logging to stdout. - logging.basicConfig(filename=None, level=logging.DEBUG) - console = logging.StreamHandler(sys.stdout) - logging.getLogger("").addHandler(console) - - def setUp(self): - super().setUp() - self.working_dir = tempfile.TemporaryDirectory() - # Run all the tests from working_dir which is our temp Android build top. - os.chdir(self.working_dir.name) - # Extract envsetup.zip which contains the envsetup.sh and other dependent - # scripts required to set up the build environments. - with resources.files("testdata").joinpath("envsetup.zip").open("rb") as p: - with zipfile.ZipFile(p, "r") as zip_f: - zip_f.extractall() - - def tearDown(self): - self.working_dir.cleanup() - super().tearDown() - - def test_does_not_log_when_logger_var_empty(self): - test_tool = TestScript.create(self.working_dir) - - self._run_script_and_wait(f""" - ANDROID_TOOL_LOGGER="" - run_tool_with_logging "FAKE_TOOL" {test_tool.executable} arg1 arg2 - """) - - test_tool.assert_called_once_with_args("arg1 arg2") - - def test_does_not_log_with_logger_unset(self): - test_tool = TestScript.create(self.working_dir) - - self._run_script_and_wait(f""" - unset ANDROID_TOOL_LOGGER - run_tool_with_logging "FAKE_TOOL" {test_tool.executable} arg1 arg2 - """) - - test_tool.assert_called_once_with_args("arg1 arg2") - - def test_log_success_with_logger_enabled(self): - test_tool = TestScript.create(self.working_dir) - test_logger = TestScript.create(self.working_dir) - - self._run_script_and_wait(f""" - ANDROID_TOOL_LOGGER="{test_logger.executable}" - run_tool_with_logging "FAKE_TOOL" {test_tool.executable} arg1 arg2 - """) - - test_tool.assert_called_once_with_args("arg1 arg2") - expected_logger_args = ( - "--tool_tag=FAKE_TOOL --start_timestamp=\d+\.\d+ --end_timestamp=" - "\d+\.\d+ --tool_args=arg1 arg2 --exit_code=0" - ) - test_logger.assert_called_once_with_args(expected_logger_args) - - def test_run_tool_output_is_same_with_and_without_logging(self): - test_tool = TestScript.create(self.working_dir, "echo 'tool called'") - test_logger = TestScript.create(self.working_dir) - - run_tool_with_logging_stdout, run_tool_with_logging_stderr = ( - self._run_script_and_wait(f""" - ANDROID_TOOL_LOGGER="{test_logger.executable}" - run_tool_with_logging "FAKE_TOOL" {test_tool.executable} arg1 arg2 - """) - ) - - run_tool_without_logging_stdout, run_tool_without_logging_stderr = ( - self._run_script_and_wait(f""" - ANDROID_TOOL_LOGGER="{test_logger.executable}" - {test_tool.executable} arg1 arg2 - """) - ) - - self.assertEqual( - run_tool_with_logging_stdout, run_tool_without_logging_stdout - ) - self.assertEqual( - run_tool_with_logging_stderr, run_tool_without_logging_stderr - ) - - def test_logger_output_is_suppressed(self): - test_tool = TestScript.create(self.working_dir) - test_logger = TestScript.create(self.working_dir, "echo 'logger called'") - - run_tool_with_logging_output, _ = self._run_script_and_wait(f""" - ANDROID_TOOL_LOGGER="{test_logger.executable}" - run_tool_with_logging "FAKE_TOOL" {test_tool.executable} arg1 arg2 - """) - - self.assertNotIn("logger called", run_tool_with_logging_output) - - def test_logger_error_is_suppressed(self): - test_tool = TestScript.create(self.working_dir) - test_logger = TestScript.create( - self.working_dir, "echo 'logger failed' > /dev/stderr; exit 1" - ) - - _, err = self._run_script_and_wait(f""" - ANDROID_TOOL_LOGGER="{test_logger.executable}" - run_tool_with_logging "FAKE_TOOL" {test_tool.executable} arg1 arg2 - """) - - self.assertNotIn("logger failed", err) - - def test_log_success_when_tool_interrupted(self): - test_tool = TestScript.create(self.working_dir, script_body="sleep 100") - test_logger = TestScript.create(self.working_dir) - - process = self._run_script_in_build_env(f""" - ANDROID_TOOL_LOGGER="{test_logger.executable}" - run_tool_with_logging "FAKE_TOOL" {test_tool.executable} arg1 arg2 - """) - - pgid = os.getpgid(process.pid) - # Give sometime for the subprocess to start. - time.sleep(1) - # Kill the subprocess and any processes created in the same group. - os.killpg(pgid, signal.SIGINT) - - returncode, _, _ = self._wait_for_process(process) - self.assertEqual(returncode, INTERRUPTED_RETURN_CODE) - - expected_logger_args = ( - "--tool_tag=FAKE_TOOL --start_timestamp=\d+\.\d+ --end_timestamp=" - "\d+\.\d+ --tool_args=arg1 arg2 --exit_code=130" - ) - test_logger.assert_called_once_with_args(expected_logger_args) - - def test_logger_can_be_toggled_on(self): - test_tool = TestScript.create(self.working_dir) - test_logger = TestScript.create(self.working_dir) - - self._run_script_and_wait(f""" - ANDROID_TOOL_LOGGER="" - ANDROID_TOOL_LOGGER="{test_logger.executable}" - run_tool_with_logging "FAKE_TOOL" {test_tool.executable} arg1 arg2 - """) - - test_logger.assert_called_with_times(1) - - def test_logger_can_be_toggled_off(self): - test_tool = TestScript.create(self.working_dir) - test_logger = TestScript.create(self.working_dir) - - self._run_script_and_wait(f""" - ANDROID_TOOL_LOGGER="{test_logger.executable}" - ANDROID_TOOL_LOGGER="" - run_tool_with_logging "FAKE_TOOL" {test_tool.executable} arg1 arg2 - """) - - test_logger.assert_not_called() - - def test_integration_tool_event_logger_dry_run(self): - test_tool = TestScript.create(self.working_dir) - logger_path = self._import_logger() - - self._run_script_and_wait(f""" - TMPDIR="{self.working_dir.name}" - ANDROID_TOOL_LOGGER="{logger_path}" - ANDROID_TOOL_LOGGER_EXTRA_ARGS="--dry_run" - run_tool_with_logging "FAKE_TOOL" {test_tool.executable} arg1 arg2 - """) - - self._assert_logger_dry_run() - - def test_tool_args_do_not_fail_logger(self): - test_tool = TestScript.create(self.working_dir) - logger_path = self._import_logger() - - self._run_script_and_wait(f""" - TMPDIR="{self.working_dir.name}" - ANDROID_TOOL_LOGGER="{logger_path}" - ANDROID_TOOL_LOGGER_EXTRA_ARGS="--dry_run" - run_tool_with_logging "FAKE_TOOL" {test_tool.executable} --tool-arg1 - """) - - self._assert_logger_dry_run() - - def _import_logger(self) -> Path: - logger = "tool_event_logger" - logger_path = Path(self.working_dir.name).joinpath(logger) - with resources.as_file(resources.files("testdata").joinpath(logger)) as p: - shutil.copy(p, logger_path) - Path.chmod(logger_path, 0o755) - return logger_path - - def _assert_logger_dry_run(self): - log_files = glob.glob(self.working_dir.name + "/tool_event_logger_*/*.log") - self.assertEqual(len(log_files), 1) - - with open(log_files[0], "r") as f: - lines = f.readlines() - self.assertEqual(len(lines), 1) - self.assertIn("dry run", lines[0]) - - def _create_build_env_script(self) -> str: - return f""" - source {Path(self.working_dir.name).joinpath("build/make/envsetup.sh")} - """ - - def _run_script_and_wait(self, test_script: str) -> tuple[str, str]: - process = self._run_script_in_build_env(test_script) - returncode, out, err = self._wait_for_process(process) - logging.debug("script stdout: %s", out) - logging.debug("script stderr: %s", err) - self.assertEqual(returncode, EXII_RETURN_CODE) - return out, err - - def _run_script_in_build_env(self, test_script: str) -> subprocess.Popen: - setup_build_env_script = self._create_build_env_script() - return subprocess.Popen( - setup_build_env_script + test_script, - shell=True, - stdout=subprocess.PIPE, - stderr=subprocess.PIPE, - text=True, - start_new_session=True, - executable="/bin/bash", - ) - - def _wait_for_process( - self, process: subprocess.Popen - ) -> tuple[int, str, str]: - pgid = os.getpgid(process.pid) - out, err = process.communicate() - # Wait for all process in the same group to complete since the logger runs - # as a separate detached process. - self._wait_for_process_group(pgid) - return (process.returncode, out, err) - - def _wait_for_process_group(self, pgid: int, timeout: int = 5): - """Waits for all subprocesses within the process group to complete.""" - start_time = time.time() - while True: - if time.time() - start_time > timeout: - raise TimeoutError( - f"Process group did not complete after {timeout} seconds" - ) - for pid in os.listdir("/proc"): - if pid.isdigit(): - try: - if os.getpgid(int(pid)) == pgid: - time.sleep(0.1) - break - except (FileNotFoundError, PermissionError, ProcessLookupError): - pass - else: - # All processes have completed. - break - - -@dataclasses.dataclass -class TestScript: - executable: Path - output_file: Path - - def create(temp_dir: Path, script_body: str = ""): - with tempfile.NamedTemporaryFile(dir=temp_dir.name, delete=False) as f: - output_file = f.name - - with tempfile.NamedTemporaryFile(dir=temp_dir.name, delete=False) as f: - executable = f.name - executable_contents = textwrap.dedent(f""" - #!/bin/bash - - echo "${{@}}" >> {output_file} - {script_body} - """) - f.write(executable_contents.encode("utf-8")) - - Path.chmod(f.name, os.stat(f.name).st_mode | stat.S_IEXEC) - - return TestScript(executable, output_file) - - def assert_called_with_times(self, expected_call_times: int): - lines = self._read_contents_from_output_file() - assert len(lines) == expected_call_times, ( - f"Expect to call {expected_call_times} times, but actually called" - f" {len(lines)} times." - ) - - def assert_called_with_args(self, expected_args: str): - lines = self._read_contents_from_output_file() - assert len(lines) > 0 - assert re.search(expected_args, lines[0]), ( - f"Expect to call with args {expected_args}, but actually called with" - f" args {lines[0]}." - ) - - def assert_not_called(self): - self.assert_called_with_times(0) - - def assert_called_once_with_args(self, expected_args: str): - self.assert_called_with_times(1) - self.assert_called_with_args(expected_args) - - def _read_contents_from_output_file(self) -> list[str]: - with open(self.output_file, "r") as f: - return f.readlines() - - -if __name__ == "__main__": - unittest.main()