Add Git Trace2 event logging Emits Git Trace2 JSON events when GIT_TRACE2_EVENT is set in the environment or trace2.eventTarget is configured in git so that repohook execution and per-hook latency can be recorded by Trace2 event consumers. Bug: 399825642 Test: ./pre-upload.py --project platform/tools/repohooks HEAD Change-Id: Ia749338035c64eb4d9aa9c5604698cabe37b5941 Reviewed-on: https://gerrit-review.googlesource.com/c/git-repohooks/+/613822 Reviewed-by: Gavin Mak <gavinmak@google.com> Tested-by: George Engelbrecht <engeg@google.com> Commit-Queue: George Engelbrecht <engeg@google.com>
diff --git a/PREUPLOAD.cfg b/PREUPLOAD.cfg index 85b9d65..2df12cd 100644 --- a/PREUPLOAD.cfg +++ b/PREUPLOAD.cfg
@@ -5,6 +5,7 @@ results_unittest = ./rh/results_unittest.py shell_unittest = ./rh/shell_unittest.py terminal_unittest = ./rh/terminal_unittest.py +trace_unittest = ./rh/trace_unittest.py utils_unittest = ./rh/utils_unittest.py android_test_mapping_format_unittest = ./tools/android_test_mapping_format_unittest.py clang-format unittest = ./tools/clang-format_unittest.py
diff --git a/pre-upload.py b/pre-upload.py index 66dd0d8..0f589c2 100755 --- a/pre-upload.py +++ b/pre-upload.py
@@ -49,6 +49,7 @@ import rh.hooks import rh.results import rh.terminal +import rh.trace import rh.utils @@ -445,7 +446,8 @@ def _run_hook(hook, project, commit, desc, diff): """Run a hook, gather stats, and process its results.""" start = datetime.datetime.now() - results = hook.hook(project, commit, desc, diff) + with rh.trace.record_region("repohook", hook.name, msg=commit): + results = hook.hook(project, commit, desc, diff) (error, warning) = _process_hook_results(results) duration = datetime.datetime.now() - start return (hook, results, error, warning, duration) @@ -586,24 +588,30 @@ Returns: True if everything passed, else False. """ - results = [] - for project, worktree in zip(project_list, worktree_list): - result = _run_project_hooks( - project, - proj_dir=worktree, - jobs=jobs, - from_git=from_git, - commit_list=commit_list, - ) - results.append(result) - if result: - # If a repo had failures, add a blank line to help break up the - # output. If there were no failures, then the output should be - # very minimal, so we don't add it then. - print("", file=sys.stderr) + rh.trace.start_session() + ret = False + try: + results = [] + for project, worktree in zip(project_list, worktree_list): + result = _run_project_hooks( + project, + proj_dir=worktree, + jobs=jobs, + from_git=from_git, + commit_list=commit_list, + ) + results.append(result) + if result: + # If a repo had failures, add a blank line to help break up the + # output. If there were no failures, then the output should be + # very minimal, so we don't add it then. + print("", file=sys.stderr) - _attempt_fixes(results, yes=yes) - return not any(results) + _attempt_fixes(results, yes=yes) + ret = not any(results) + finally: + rh.trace.exit_session(0 if ret else 1) + return ret def main(project_list, worktree_list=None, yes=False, **_kwargs):
diff --git a/rh/git.py b/rh/git.py index 072bbb6..7476a42 100644 --- a/rh/git.py +++ b/rh/git.py
@@ -70,10 +70,19 @@ return full_upstream.replace("heads", "remotes/" + remote) -def get_commit_for_ref(ref: str) -> str: +def get_config(key: str, cwd: Optional[str] = None) -> Optional[str]: + """Returns the value for a git config key, or None if unset.""" + cmd = ["git", "config", "--get", key] + result = rh.utils.run(cmd, capture_output=True, check=False, cwd=cwd) + if result.returncode == 0: + return result.stdout.strip() + return None + + +def get_commit_for_ref(ref: str, cwd: Optional[str] = None) -> str: """Returns the latest commit for this ref.""" cmd = ["git", "rev-parse", ref] - result = rh.utils.run(cmd, capture_output=True) + result = rh.utils.run(cmd, capture_output=True, cwd=cwd) return result.stdout.strip()
diff --git a/rh/trace.py b/rh/trace.py new file mode 100644 index 0000000..4760dba --- /dev/null +++ b/rh/trace.py
@@ -0,0 +1,210 @@ +# Copyright (C) 2026 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. + +"""Git Trace2 telemetry event logging for repohooks. + +When GIT_TRACE2_EVENT is set in the environment or trace2.eventTarget is +configured in git, this module emits JSON Trace2 events (conforming to Git's +trace2 event API) so that local repohooks execution and per-hook latency can +be logged and analyzed by downstream Trace2 event consumers. +""" + +import contextlib +import datetime +import functools +import json +import os +import socket +import sys +import tempfile +import threading +from typing import Any, Dict, Iterator, Optional + +import rh.git +import rh.utils + + +_START_TIME = datetime.datetime.now(datetime.timezone.utc) + + +@functools.lru_cache(maxsize=1) +def get_trace2_target() -> Optional[str]: + """Return the configured Git Trace2 event target, or None if disabled.""" + target = os.environ.get("GIT_TRACE2_EVENT", "").strip() + if not target: + try: + target = rh.git.get_config("trace2.eventTarget") or "" + target = target.strip() + except (OSError, ValueError, rh.utils.CalledProcessError): + target = "" + if not target or target.lower() in {"0", "false", "no", "off"}: + return None + if target.lower() in {"1", "true", "yes", "on", "stderr"}: + return "stderr" + if os.path.isdir(target): + try: + with tempfile.NamedTemporaryFile( + dir=target, + prefix=f"repohooks-P{os.getpid():08x}-", + delete=False, + ) as fp: + return fp.name + except OSError: + return None + return target + + +def get_sid() -> str: + """Return the hierarchical Trace2 session ID for this repohooks process.""" + parent = os.environ.get( + "GIT_TRACE2_PARENT_SID", + os.environ.get("GIT_TRACE2_EVENT_SID", ""), + ).strip() + pid_sid = f"repohooks-P{os.getpid():08x}" + return f"{parent}/{pid_sid}" if parent else pid_sid + + +def _get_utc_timestamp() -> str: + """Return an ISO 8601 UTC timestamp string required by Git Trace2.""" + now = datetime.datetime.now(datetime.timezone.utc) + return now.strftime("%Y-%m-%dT%H:%M:%S.%f") + "Z" + + +def _get_elapsed_seconds() -> float: + """Return float seconds elapsed since rh.trace module initialization.""" + now = datetime.datetime.now(datetime.timezone.utc) + return (now - _START_TIME).total_seconds() + + +def _get_exe_version() -> str: + """Return repohooks git commit or version string for the version event.""" + try: + repohooks_dir = os.path.dirname(os.path.realpath(__file__)) + return rh.git.get_commit_for_ref("HEAD", cwd=repohooks_dir) + except (OSError, ValueError, rh.utils.CalledProcessError): + return "repohooks" + + +def _write_trace2_event(event_dict: Dict[str, Any]) -> None: + """Write a formatted JSON Trace2 event to the configured target.""" + target = get_trace2_target() + if not target: + return + + event_dict.setdefault("sid", get_sid()) + event_dict.setdefault("thread", threading.current_thread().name) + event_dict.setdefault("time", _get_utc_timestamp()) + + payload = (json.dumps(event_dict) + "\n").encode("utf-8") + + try: + if target == "stderr": + try: + sys.stderr.buffer.write(payload) + sys.stderr.buffer.flush() + except AttributeError: + sys.stderr.write(payload.decode("utf-8")) + sys.stderr.flush() + elif target.startswith("af_unix:"): + sock_type = ( + socket.SOCK_DGRAM + if target.startswith("af_unix:dgram:") + else socket.SOCK_STREAM + ) + sock_path = target.split(":", 2)[-1] + with socket.socket(socket.AF_UNIX, sock_type) as sock: + if sock_type == socket.SOCK_STREAM: + sock.settimeout(0.5) + sock.connect(sock_path) + sock.sendall(payload) + else: + sock.sendto(payload, sock_path) + else: + with open(target, "ab") as fp: + fp.write(payload) + except OSError: + # Silently ignore write errors so tracing never breaks hooks. + pass + + +def start_session() -> None: + """Emit Trace2 version and start events when repohooks begins execution.""" + if not get_trace2_target(): + return + + _write_trace2_event( + { + "event": "version", + "evt": "2", + "exe": _get_exe_version(), + } + ) + _write_trace2_event( + { + "event": "start", + "t_abs": _get_elapsed_seconds(), + "argv": sys.argv, + } + ) + + +def exit_session(return_code: int = 0) -> None: + """Emit Trace2 exit event when repohooks finishes execution.""" + if not get_trace2_target(): + return + + _write_trace2_event( + { + "event": "exit", + "t_abs": _get_elapsed_seconds(), + "code": return_code, + } + ) + + +@contextlib.contextmanager +def record_region(category: str, label: str, msg: str = "") -> Iterator[None]: + """Context manager to emit region_enter and region_leave Trace2 events.""" + if not get_trace2_target(): + # Must yield once to satisfy contextmanager protocol when disabled. + yield + return + + start_time = datetime.datetime.now(datetime.timezone.utc) + enter_event = { + "event": "region_enter", + "category": category, + "label": label, + "nesting": 1, + } + if msg: + enter_event["msg"] = msg + _write_trace2_event(enter_event) + + try: + yield + finally: + end_time = datetime.datetime.now(datetime.timezone.utc) + elapsed_us = int((end_time - start_time).total_seconds() * 1000000) + leave_event = { + "event": "region_leave", + "category": category, + "label": label, + "nesting": 1, + "t_rel": round((end_time - start_time).total_seconds(), 6), + "relative_time_us": elapsed_us, + } + if msg: + leave_event["msg"] = msg + _write_trace2_event(leave_event)
diff --git a/rh/trace_unittest.py b/rh/trace_unittest.py new file mode 100755 index 0000000..f5dc1ea --- /dev/null +++ b/rh/trace_unittest.py
@@ -0,0 +1,131 @@ +#!/usr/bin/env python3 +# Copyright (C) 2026 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. + +"""Unittests for the trace module.""" + +import json +import os +from pathlib import Path +import shutil +import sys +import tempfile +import threading +import unittest + + +THIS_FILE = Path(__file__).resolve() +THIS_DIR = THIS_FILE.parent +sys.path.insert(0, str(THIS_DIR.parent)) + +# pylint: disable=wrong-import-position +import rh.trace + + +class TraceTest(unittest.TestCase): + """Test Git Trace2 event emission in rh.trace.""" + + def setUp(self): + self.tempdir = tempfile.mkdtemp() + self.trace_file = os.path.join(self.tempdir, "trace.json") + os.environ["GIT_TRACE2_EVENT"] = self.trace_file + os.environ["GIT_TRACE2_PARENT_SID"] = "test-repo-sid" + rh.trace.get_trace2_target.cache_clear() + + def tearDown(self): + os.environ.pop("GIT_TRACE2_EVENT", None) + os.environ.pop("GIT_TRACE2_PARENT_SID", None) + rh.trace.get_trace2_target.cache_clear() + shutil.rmtree(self.tempdir, ignore_errors=True) + + def test_record_region_emits_enter_and_leave(self): + """Verify record_region writes region_enter and region_leave events.""" + with rh.trace.record_region("repohook", "ktfmt", msg="commit-123"): + pass + + with open(self.trace_file, "r", encoding="utf-8") as fp: + events = [json.loads(line) for line in fp if line.strip()] + + self.assertEqual(len(events), 2) + self.assertEqual(events[0]["event"], "region_enter") + self.assertEqual(events[0]["category"], "repohook") + self.assertEqual(events[0]["label"], "ktfmt") + self.assertEqual(events[0]["msg"], "commit-123") + self.assertEqual(events[0]["nesting"], 1) + self.assertEqual(events[0]["thread"], threading.current_thread().name) + self.assertTrue( + events[0]["sid"].startswith("test-repo-sid/repohooks-P") + ) + + self.assertEqual(events[1]["event"], "region_leave") + self.assertEqual(events[1]["category"], "repohook") + self.assertEqual(events[1]["label"], "ktfmt") + self.assertEqual(events[1]["nesting"], 1) + self.assertIn("t_rel", events[1]) + self.assertIn("relative_time_us", events[1]) + + def test_disabled_tracing_is_silent(self): + """Verify nothing is written when GIT_TRACE2_EVENT is unset.""" + os.environ.pop("GIT_TRACE2_EVENT", None) + rh.trace.get_trace2_target.cache_clear() + with rh.trace.record_region("repohook", "ktfmt"): + pass + self.assertFalse(os.path.exists(self.trace_file)) + + def test_get_trace2_target(self): + """Verify target resolution and disable strings.""" + os.environ["GIT_TRACE2_EVENT"] = "0" + rh.trace.get_trace2_target.cache_clear() + self.assertIsNone(rh.trace.get_trace2_target()) + + os.environ["GIT_TRACE2_EVENT"] = "false" + rh.trace.get_trace2_target.cache_clear() + self.assertIsNone(rh.trace.get_trace2_target()) + + os.environ["GIT_TRACE2_EVENT"] = "1" + rh.trace.get_trace2_target.cache_clear() + self.assertEqual(rh.trace.get_trace2_target(), "stderr") + + os.environ["GIT_TRACE2_EVENT"] = "/path/to/trace" + rh.trace.get_trace2_target.cache_clear() + self.assertEqual(rh.trace.get_trace2_target(), "/path/to/trace") + + def test_directory_target(self): + """Verify directory target creates a file and writes events to it.""" + os.environ["GIT_TRACE2_EVENT"] = self.tempdir + rh.trace.get_trace2_target.cache_clear() + + rh.trace.start_session() + with rh.trace.record_region("repohook", "black", msg="commit-456"): + pass + rh.trace.exit_session(0) + + target = rh.trace.get_trace2_target() + self.assertIsNotNone(target) + self.assertTrue(target.startswith(self.tempdir)) + self.assertTrue(os.path.basename(target).startswith("repohooks-P")) + self.assertTrue(os.path.exists(target)) + + with open(target, "r", encoding="utf-8") as fp: + events = [json.loads(line) for line in fp if line.strip()] + + event_names = [e.get("event") for e in events] + self.assertEqual( + event_names, + ["version", "start", "region_enter", "region_leave", "exit"], + ) + + +if __name__ == "__main__": + unittest.main()