# Copyright (C) 2020 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 git_trace2_event_log.py module.""" import contextlib import io import json import os import re import socket import tempfile import threading from typing import Any, Dict, List, Optional from unittest import mock import pytest import git_trace2_event_log import platform_utils def server_logging_thread( socket_path: str, server_ready: threading.Event, received_traces: List[str], ) -> None: """Helper function to receive logs over a Unix domain socket. Appends received messages on the provided socket and appends to received_traces. Args: socket_path: path to a Unix domain socket on which to listen for traces server_ready: event set when the server is ready to accept connections received_traces: a list to which received traces will be appended (after decoding to a utf-8 string). """ platform_utils.remove(socket_path, missing_ok=True) data = b"" with socket.socket(socket.AF_UNIX, socket.SOCK_STREAM) as sock: sock.bind(socket_path) sock.listen(0) server_ready.set() with sock.accept()[0] as conn: while True: recved = conn.recv(4096) if not recved: break data += recved received_traces.extend(data.decode("utf-8").splitlines()) PARENT_SID_KEY = "GIT_TRACE2_PARENT_SID" PARENT_SID_VALUE = "parent_sid" SELF_SID_REGEX = r"repo-\d+T\d+Z-.*" FULL_SID_REGEX = rf"^{PARENT_SID_VALUE}/{SELF_SID_REGEX}" @pytest.fixture def event_log() -> git_trace2_event_log.EventLog: """Fixture for the EventLog module.""" # By default we initialize with the expected case where # repo launches us (so GIT_TRACE2_PARENT_SID is set). env = {PARENT_SID_KEY: PARENT_SID_VALUE} return git_trace2_event_log.EventLog(env=env) def verify_common_keys( log_entry: Dict[str, Any], expected_event_name: Optional[str] = None, full_sid: bool = True, ) -> None: """Helper function to verify common event log keys.""" assert "event" in log_entry assert "sid" in log_entry assert "thread" in log_entry assert "time" in log_entry # Do basic data format validation. if expected_event_name: assert expected_event_name == log_entry["event"] if full_sid: assert re.match(FULL_SID_REGEX, log_entry["sid"]) else: assert re.match(SELF_SID_REGEX, log_entry["sid"]) assert re.match(r"^\d+-\d+-\d+T\d+:\d+:\d+\.\d+\+00:00$", log_entry["time"]) def read_log(log_path: str) -> List[Dict[str, Any]]: """Helper function to read log data into a list.""" log_data = [] with open(log_path, mode="rb") as f: for line in f: log_data.append(json.loads(line)) return log_data def remove_prefix(s: str, prefix: str) -> str: """Return a copy string after removing |prefix| from |s|, if present or the original string.""" if s.startswith(prefix): return s[len(prefix) :] else: return s def test_initial_state_with_parent_sid( event_log: git_trace2_event_log.EventLog, ) -> None: """Test initial state when 'GIT_TRACE2_PARENT_SID' is set by parent.""" assert re.match(FULL_SID_REGEX, event_log.full_sid) def test_initial_state_no_parent_sid() -> None: """Test initial state when 'GIT_TRACE2_PARENT_SID' is not set.""" # Setup an empty environment dict (no parent sid). event_log = git_trace2_event_log.EventLog(env={}) assert re.match(SELF_SID_REGEX, event_log.full_sid) def test_version_event(event_log: git_trace2_event_log.EventLog) -> None: """Test 'version' event data is valid. Verify that the 'version' event is written even when no other events are added. Expected event log: """ with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: log_path = event_log.Write(path=tempdir) log_data = read_log(log_path) # A log with no added events should only have the version entry. assert len(log_data) == 1 version_event = log_data[0] verify_common_keys(version_event, expected_event_name="version") # Check for 'version' event specific fields. assert "evt" in version_event assert "exe" in version_event # Verify "evt" version field is a string. assert isinstance(version_event["evt"], str) def test_start_event(event_log: git_trace2_event_log.EventLog) -> None: """Test and validate 'start' event data is valid. Expected event log: """ event_log.StartEvent([]) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: log_path = event_log.Write(path=tempdir) log_data = read_log(log_path) assert len(log_data) == 2 start_event = log_data[1] verify_common_keys(log_data[0], expected_event_name="version") verify_common_keys(start_event, expected_event_name="start") # Check for 'start' event specific fields. assert "argv" in start_event assert isinstance(start_event["argv"], list) def test_exit_event_result_none( event_log: git_trace2_event_log.EventLog, ) -> None: """Test 'exit' event data is valid when result is None. We expect None result to be converted to 0 in the exit event data. Expected event log: """ event_log.ExitEvent(None) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: log_path = event_log.Write(path=tempdir) log_data = read_log(log_path) assert len(log_data) == 2 exit_event = log_data[1] verify_common_keys(log_data[0], expected_event_name="version") verify_common_keys(exit_event, expected_event_name="exit") # Check for 'exit' event specific fields. assert "code" in exit_event # 'None' result should convert to 0 (successful) return code. assert exit_event["code"] == 0 def test_exit_event_result_integer( event_log: git_trace2_event_log.EventLog, ) -> None: """Test 'exit' event data is valid when result is an integer. Expected event log: """ event_log.ExitEvent(2) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: log_path = event_log.Write(path=tempdir) log_data = read_log(log_path) assert len(log_data) == 2 exit_event = log_data[1] verify_common_keys(log_data[0], expected_event_name="version") verify_common_keys(exit_event, expected_event_name="exit") # Check for 'exit' event specific fields. assert "code" in exit_event assert exit_event["code"] == 2 def test_command_event(event_log: git_trace2_event_log.EventLog) -> None: """Test and validate 'command' event data is valid. Expected event log: """ event_log.CommandEvent(name="repo", subcommands=["init", "this"]) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: log_path = event_log.Write(path=tempdir) log_data = read_log(log_path) assert len(log_data) == 2 command_event = log_data[1] verify_common_keys(log_data[0], expected_event_name="version") verify_common_keys(command_event, expected_event_name="cmd_name") # Check for 'command' event specific fields. assert "name" in command_event assert command_event["name"] == "repo-init-this" def test_def_params_event_repo_config( event_log: git_trace2_event_log.EventLog, ) -> None: """Test 'def_params' event data outputs only repo config keys. Expected event log: """ config = { "git.foo": "bar", "repo.partialclone": "true", "repo.partialclonefilter": "blob:none", } event_log.DefParamRepoEvents(config) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: log_path = event_log.Write(path=tempdir) log_data = read_log(log_path) assert len(log_data) == 3 def_param_events = log_data[1:] verify_common_keys(log_data[0], expected_event_name="version") for event in def_param_events: verify_common_keys(event, expected_event_name="def_param") # Check for 'def_param' event specific fields. assert "param" in event assert "value" in event assert event["param"].startswith("repo.") def test_def_params_event_no_repo_config( event_log: git_trace2_event_log.EventLog, ) -> None: """Test 'def_params' event data won't output non-repo config keys. Expected event log: """ config = { "git.foo": "bar", "git.core.foo2": "baz", } event_log.DefParamRepoEvents(config) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: log_path = event_log.Write(path=tempdir) log_data = read_log(log_path) assert len(log_data) == 1 verify_common_keys(log_data[0], expected_event_name="version") def test_data_event_config(event_log: git_trace2_event_log.EventLog) -> None: """Test 'data' event data outputs all config keys. Expected event log: """ config = { "git.foo": "bar", "repo.partialclone": "false", "repo.syncstate.superproject.hassuperprojecttag": "true", "repo.syncstate.superproject.sys.argv": ["--", "sync", "protobuf"], "repo.syncstate.emptykey": "", } prefix_value = "prefix" event_log.LogDataConfigEvents(config, prefix_value) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: log_path = event_log.Write(path=tempdir) log_data = read_log(log_path) assert len(log_data) == 6 data_events = log_data[1:] verify_common_keys(log_data[0], expected_event_name="version") for event in data_events: verify_common_keys(event) # Check for 'data' event specific fields. assert "key" in event assert "value" in event key = event["key"] key = remove_prefix(key, f"{prefix_value}/") value = event["value"] assert event_log.GetDataEventName(value) == event["event"] assert key in config assert value == config[key] def test_error_event(event_log: git_trace2_event_log.EventLog) -> None: """Test and validate 'error' event data is valid. Expected event log: """ msg = "invalid option: --cahced" fmt = "invalid option: %s" event_log.ErrorEvent(msg, fmt) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: log_path = event_log.Write(path=tempdir) log_data = read_log(log_path) assert len(log_data) == 2 error_event = log_data[1] verify_common_keys(log_data[0], expected_event_name="version") verify_common_keys(error_event, expected_event_name="error") # Check for 'error' event specific fields. assert "msg" in error_event assert "fmt" in error_event assert error_event["msg"] == f"RepoErrorEvent:{msg}" assert error_event["fmt"] == f"RepoErrorEvent:{fmt}" def test_write_with_filename(event_log: git_trace2_event_log.EventLog) -> None: """Test Write() with a path to a file exits with None.""" assert event_log.Write(path="path/to/file") is None def test_write_with_git_config( tmp_path, event_log: git_trace2_event_log.EventLog, ) -> None: """Test Write() uses the git config path when 'git config' call succeeds.""" with mock.patch.object( event_log, "_GetEventTargetPath", return_value=str(tmp_path), ): assert os.path.dirname(event_log.Write()) == str(tmp_path) def test_write_no_git_config(event_log: git_trace2_event_log.EventLog) -> None: """Test Write() with no git config variable present exits with None.""" with mock.patch.object(event_log, "_GetEventTargetPath", return_value=None): assert event_log.Write() is None def test_write_non_string(event_log: git_trace2_event_log.EventLog) -> None: """Test Write() with non-string type for |path| throws TypeError.""" with pytest.raises(TypeError): event_log.Write(path=1234) @pytest.mark.skipif( not hasattr(socket, "AF_UNIX"), reason="Requires AF_UNIX sockets" ) def test_write_socket(event_log: git_trace2_event_log.EventLog) -> None: """Test Write() with Unix domain socket and validate received traces.""" received_traces: List[str] = [] with tempfile.TemporaryDirectory(prefix="test_server_sockets") as tempdir: socket_path = os.path.join(tempdir, "server.sock") server_ready = threading.Event() # Start "server" listening on Unix domain socket at socket_path. server_thread = threading.Thread( target=server_logging_thread, args=(socket_path, server_ready, received_traces), ) try: server_thread.start() server_ready.wait(timeout=120) event_log.StartEvent([]) path = event_log.Write(path=f"af_unix:{socket_path}") finally: server_thread.join(timeout=5) assert path == f"af_unix:stream:{socket_path}" assert len(received_traces) == 2 version_event = json.loads(received_traces[0]) start_event = json.loads(received_traces[1]) verify_common_keys(version_event, expected_event_name="version") verify_common_keys(start_event, expected_event_name="start") # Check for 'start' event specific fields. assert "argv" in start_event assert isinstance(start_event["argv"], list) class TestEventLogVerbose: """TestCase for the EventLog module verbose logging.""" def test_write_socket_error_no_verbose(self) -> None: """Test Write() suppression of socket errors when not verbose.""" event_log = git_trace2_event_log.EventLog(env={}) event_log.verbose = False with contextlib.redirect_stderr( io.StringIO() ) as mock_stderr, mock.patch("socket.socket", side_effect=OSError): event_log.Write(path="af_unix:stream:/tmp/test_sock") assert mock_stderr.getvalue() == "" def test_write_socket_error_verbose(self) -> None: """Test Write() printing of socket errors when verbose.""" event_log = git_trace2_event_log.EventLog(env={}) event_log.verbose = True with contextlib.redirect_stderr( io.StringIO() ) as mock_stderr, mock.patch( "socket.socket", side_effect=OSError("Mock error") ): event_log.Write(path="af_unix:stream:/tmp/test_sock") assert ( "git trace2 logging failed: Mock error" in mock_stderr.getvalue() ) def test_write_file_error_no_verbose(self) -> None: """Test Write() suppression of file errors when not verbose.""" event_log = git_trace2_event_log.EventLog(env={}) event_log.verbose = False with contextlib.redirect_stderr( io.StringIO() ) as mock_stderr, mock.patch( "tempfile.NamedTemporaryFile", side_effect=FileExistsError ): event_log.Write(path="/tmp") assert mock_stderr.getvalue() == "" def test_write_file_error_verbose(self) -> None: """Test Write() printing of file errors when verbose.""" event_log = git_trace2_event_log.EventLog(env={}) event_log.verbose = True with contextlib.redirect_stderr( io.StringIO() ) as mock_stderr, mock.patch( "tempfile.NamedTemporaryFile", side_effect=FileExistsError("Mock error"), ): event_log.Write(path="/tmp") assert ( "git trace2 logging failed: FileExistsError" in mock_stderr.getvalue() )