Make git trace2 logging errors conditional on verbose mode. Add a verbose attribute to the EventLog class, defaulting to False. Error messages printed to sys.stderr within the EventLog.Write method are now guarded by this verbose flag. In main.py, set EventLog.verbose to True if the command-line --verbose option is used. This prevents trace2 logging failures from being printed to stderr unless verbose output is explicitly requested. PROMPT=convert all git trace2 logging print messages to verbose only logging BUG: b/479811034 Change-Id: I8757ee52117d766f2f3ec47856db64cc4f51143c Reviewed-on: https://gerrit-review.googlesource.com/c/git-repo/+/547542 Tested-by: Sam Saccone <samccone@google.com> Reviewed-by: Julia Tuttle <juliatuttle@google.com> Reviewed-by: Gavin Mak <gavinmak@google.com>
diff --git a/git_trace2_event_log_base.py b/git_trace2_event_log_base.py index 56db7a8..1a59fee 100644 --- a/git_trace2_event_log_base.py +++ b/git_trace2_event_log_base.py
@@ -68,6 +68,7 @@ global p_init_count p_init_count += 1 self._log = [] + self.verbose = False # Try to get session-id (sid) from environment (setup in repo launcher). KEY = "GIT_TRACE2_PARENT_SID" if env is None: @@ -309,10 +310,12 @@ # ignore the attempt and continue to DGRAM below. Otherwise, # issue a warning. if err.errno != errno.EPROTOTYPE: - print( - f"repo: warning: git trace2 logging failed: {err}", - file=sys.stderr, - ) + if self.verbose: + print( + "repo: warning: git trace2 logging failed:", + f"{err}", + file=sys.stderr, + ) return None if socket_type == socket.SOCK_DGRAM or socket_type is None: try: @@ -322,18 +325,20 @@ self._WriteLog(lambda bs: sock.sendto(bs, path)) return f"af_unix:dgram:{path}" except OSError as err: - print( - f"repo: warning: git trace2 logging failed: {err}", - file=sys.stderr, - ) + if self.verbose: + print( + f"repo: warning: git trace2 logging failed: {err}", + file=sys.stderr, + ) return None # Tried to open a socket but couldn't connect (SOCK_STREAM) or write # (SOCK_DGRAM). - print( - "repo: warning: git trace2 logging failed: could not write to " - "socket", - file=sys.stderr, - ) + if self.verbose: + print( + "repo: warning: git trace2 logging failed: could not" + "write to socket", + file=sys.stderr, + ) return None # Path is an absolute path @@ -348,9 +353,10 @@ self._WriteLog(f.write) log_path = f.name except FileExistsError as err: - print( - "repo: warning: git trace2 logging failed: %r" % err, - file=sys.stderr, - ) + if self.verbose: + print( + "repo: warning: git trace2 logging failed: %r" % err, + file=sys.stderr, + ) return None return log_path
diff --git a/main.py b/main.py index 424ad91..c559222 100755 --- a/main.py +++ b/main.py
@@ -337,6 +337,9 @@ ) return 1 + cmd.CommonValidateOptions(copts, cargs) + git_trace2_event_log.verbose = copts.verbose + if gopts.pager is not False and not isinstance(cmd, InteractiveCommand): config = cmd.client.globalConfig if gopts.pager: @@ -359,7 +362,6 @@ Execute the subcommand. """ nonlocal result - cmd.CommonValidateOptions(copts, cargs) cmd.ValidateOptions(copts, cargs) this_manifest_only = copts.this_manifest_only
diff --git a/tests/test_git_trace2_event_log.py b/tests/test_git_trace2_event_log.py index bbeb453..be2d09b 100644 --- a/tests/test_git_trace2_event_log.py +++ b/tests/test_git_trace2_event_log.py
@@ -14,6 +14,8 @@ """Unittests for the git_trace2_event_log.py module.""" +import contextlib +import io import json import os import socket @@ -65,13 +67,13 @@ def setUp(self): """Load the event_log module every time.""" - self._event_log_module = None + self._event_log = None # By default we initialize with the expected case where # repo launches us (so GIT_TRACE2_PARENT_SID is set). env = { self.PARENT_SID_KEY: self.PARENT_SID_VALUE, } - self._event_log_module = git_trace2_event_log.EventLog(env=env) + self._event_log = git_trace2_event_log.EventLog(env=env) self._log_data = None def verifyCommonKeys( @@ -112,13 +114,13 @@ def test_initial_state_with_parent_sid(self): """Test initial state when 'GIT_TRACE2_PARENT_SID' is set by parent.""" - self.assertRegex(self._event_log_module.full_sid, self.FULL_SID_REGEX) + self.assertRegex(self._event_log.full_sid, self.FULL_SID_REGEX) def test_initial_state_no_parent_sid(self): """Test initial state when 'GIT_TRACE2_PARENT_SID' is not set.""" # Setup an empty environment dict (no parent sid). - self._event_log_module = git_trace2_event_log.EventLog(env={}) - self.assertRegex(self._event_log_module.full_sid, self.SELF_SID_REGEX) + self._event_log = git_trace2_event_log.EventLog(env={}) + self.assertRegex(self._event_log.full_sid, self.SELF_SID_REGEX) def test_version_event(self): """Test 'version' event data is valid. @@ -130,7 +132,7 @@ <version event> """ with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: - log_path = self._event_log_module.Write(path=tempdir) + log_path = self._event_log.Write(path=tempdir) self._log_data = self.readLog(log_path) # A log with no added events should only have the version entry. @@ -150,9 +152,9 @@ <version event> <start event> """ - self._event_log_module.StartEvent([]) + self._event_log.StartEvent([]) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: - log_path = self._event_log_module.Write(path=tempdir) + log_path = self._event_log.Write(path=tempdir) self._log_data = self.readLog(log_path) self.assertEqual(len(self._log_data), 2) @@ -172,9 +174,9 @@ <version event> <exit event> """ - self._event_log_module.ExitEvent(None) + self._event_log.ExitEvent(None) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: - log_path = self._event_log_module.Write(path=tempdir) + log_path = self._event_log.Write(path=tempdir) self._log_data = self.readLog(log_path) self.assertEqual(len(self._log_data), 2) @@ -193,9 +195,9 @@ <version event> <exit event> """ - self._event_log_module.ExitEvent(2) + self._event_log.ExitEvent(2) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: - log_path = self._event_log_module.Write(path=tempdir) + log_path = self._event_log.Write(path=tempdir) self._log_data = self.readLog(log_path) self.assertEqual(len(self._log_data), 2) @@ -213,11 +215,9 @@ <version event> <command event> """ - self._event_log_module.CommandEvent( - name="repo", subcommands=["init", "this"] - ) + self._event_log.CommandEvent(name="repo", subcommands=["init", "this"]) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: - log_path = self._event_log_module.Write(path=tempdir) + log_path = self._event_log.Write(path=tempdir) self._log_data = self.readLog(log_path) self.assertEqual(len(self._log_data), 2) @@ -241,10 +241,10 @@ "repo.partialclone": "true", "repo.partialclonefilter": "blob:none", } - self._event_log_module.DefParamRepoEvents(config) + self._event_log.DefParamRepoEvents(config) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: - log_path = self._event_log_module.Write(path=tempdir) + log_path = self._event_log.Write(path=tempdir) self._log_data = self.readLog(log_path) self.assertEqual(len(self._log_data), 3) @@ -268,10 +268,10 @@ "git.foo": "bar", "git.core.foo2": "baz", } - self._event_log_module.DefParamRepoEvents(config) + self._event_log.DefParamRepoEvents(config) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: - log_path = self._event_log_module.Write(path=tempdir) + log_path = self._event_log.Write(path=tempdir) self._log_data = self.readLog(log_path) self.assertEqual(len(self._log_data), 1) @@ -292,10 +292,10 @@ "repo.syncstate.superproject.sys.argv": ["--", "sync", "protobuf"], } prefix_value = "prefix" - self._event_log_module.LogDataConfigEvents(config, prefix_value) + self._event_log.LogDataConfigEvents(config, prefix_value) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: - log_path = self._event_log_module.Write(path=tempdir) + log_path = self._event_log.Write(path=tempdir) self._log_data = self.readLog(log_path) self.assertEqual(len(self._log_data), 5) @@ -311,7 +311,7 @@ key = self.remove_prefix(key, f"{prefix_value}/") value = event["value"] self.assertEqual( - self._event_log_module.GetDataEventName(value), event["event"] + self._event_log.GetDataEventName(value), event["event"] ) self.assertTrue(key in config and value == config[key]) @@ -324,9 +324,9 @@ """ msg = "invalid option: --cahced" fmt = "invalid option: %s" - self._event_log_module.ErrorEvent(msg, fmt) + self._event_log.ErrorEvent(msg, fmt) with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: - log_path = self._event_log_module.Write(path=tempdir) + log_path = self._event_log.Write(path=tempdir) self._log_data = self.readLog(log_path) self.assertEqual(len(self._log_data), 2) @@ -341,32 +341,32 @@ def test_write_with_filename(self): """Test Write() with a path to a file exits with None.""" - self.assertIsNone(self._event_log_module.Write(path="path/to/file")) + self.assertIsNone(self._event_log.Write(path="path/to/file")) def test_write_with_git_config(self): """Test Write() uses the git config path when 'git config' call succeeds.""" with tempfile.TemporaryDirectory(prefix="event_log_tests") as tempdir: with mock.patch.object( - self._event_log_module, + self._event_log, "_GetEventTargetPath", return_value=tempdir, ): self.assertEqual( - os.path.dirname(self._event_log_module.Write()), tempdir + os.path.dirname(self._event_log.Write()), tempdir ) def test_write_no_git_config(self): """Test Write() with no git config variable present exits with None.""" with mock.patch.object( - self._event_log_module, "_GetEventTargetPath", return_value=None + self._event_log, "_GetEventTargetPath", return_value=None ): - self.assertIsNone(self._event_log_module.Write()) + self.assertIsNone(self._event_log.Write()) def test_write_non_string(self): """Test Write() with non-string type for |path| throws TypeError.""" with self.assertRaises(TypeError): - self._event_log_module.Write(path=1234) + self._event_log.Write(path=1234) @unittest.skipIf(not hasattr(socket, "AF_UNIX"), "Requires AF_UNIX sockets") def test_write_socket(self): @@ -389,10 +389,8 @@ with server_ready: server_ready.wait(timeout=120) - self._event_log_module.StartEvent([]) - path = self._event_log_module.Write( - path=f"af_unix:{socket_path}" - ) + self._event_log.StartEvent([]) + path = self._event_log.Write(path=f"af_unix:{socket_path}") finally: server_thread.join(timeout=5) @@ -405,3 +403,59 @@ # Check for 'start' event specific fields. self.assertIn("argv", start_event) self.assertIsInstance(start_event["argv"], list) + + +class EventLogVerboseTestCase(unittest.TestCase): + """TestCase for the EventLog module verbose logging.""" + + def setUp(self): + self._event_log = git_trace2_event_log.EventLog(env={}) + + def test_write_socket_error_no_verbose(self): + """Test Write() suppression of socket errors when not verbose.""" + self._event_log.verbose = False + with contextlib.redirect_stderr( + io.StringIO() + ) as mock_stderr, mock.patch("socket.socket", side_effect=OSError): + self._event_log.Write(path="af_unix:stream:/tmp/test_sock") + self.assertEqual(mock_stderr.getvalue(), "") + + def test_write_socket_error_verbose(self): + """Test Write() printing of socket errors when verbose.""" + self._event_log.verbose = True + with contextlib.redirect_stderr( + io.StringIO() + ) as mock_stderr, mock.patch( + "socket.socket", side_effect=OSError("Mock error") + ): + self._event_log.Write(path="af_unix:stream:/tmp/test_sock") + self.assertIn( + "git trace2 logging failed: Mock error", + mock_stderr.getvalue(), + ) + + def test_write_file_error_no_verbose(self): + """Test Write() suppression of file errors when not verbose.""" + self._event_log.verbose = False + with contextlib.redirect_stderr( + io.StringIO() + ) as mock_stderr, mock.patch( + "tempfile.NamedTemporaryFile", side_effect=FileExistsError + ): + self._event_log.Write(path="/tmp") + self.assertEqual(mock_stderr.getvalue(), "") + + def test_write_file_error_verbose(self): + """Test Write() printing of file errors when verbose.""" + self._event_log.verbose = True + with contextlib.redirect_stderr( + io.StringIO() + ) as mock_stderr, mock.patch( + "tempfile.NamedTemporaryFile", + side_effect=FileExistsError("Mock error"), + ): + self._event_log.Write(path="/tmp") + self.assertIn( + "git trace2 logging failed: FileExistsError", + mock_stderr.getvalue(), + )
diff --git a/tests/test_subcmds.py b/tests/test_subcmds.py index 0683f1d..3382d82 100644 --- a/tests/test_subcmds.py +++ b/tests/test_subcmds.py
@@ -135,3 +135,50 @@ # Make sure we aren't popping the wrong stuff. assert optparse.Option.CHECK_METHODS.pop(0) is _check_dest + + def test_common_validate_options(self): + """Verify CommonValidateOptions sets up expected fields.""" + for name, cls in subcmds.all_commands.items(): + cmd = cls() + opts, args = cmd.OptionParser.parse_args([]) + + # Verify the fields don't exist yet. + self.assertFalse( + hasattr(opts, "verbose"), + msg=f"{name}: has verbose before validation", + ) + self.assertFalse( + hasattr(opts, "quiet"), + msg=f"{name}: has quiet before validation", + ) + + cmd.CommonValidateOptions(opts, args) + + # Verify the fields exist now. + self.assertTrue( + hasattr(opts, "verbose"), + msg=f"{name}: missing verbose after validation", + ) + self.assertTrue( + hasattr(opts, "quiet"), + msg=f"{name}: missing quiet after validation", + ) + self.assertTrue( + hasattr(opts, "outer_manifest"), + msg=f"{name}: missing outer_manifest after validation", + ) + + def test_attribute_error_repro(self): + """Confirm that accessing verbose before CommonValidateOptions fails.""" + from subcmds.sync import Sync + + cmd = Sync() + opts, args = cmd.OptionParser.parse_args([]) + + # This confirms that without the fix in main.py, an AttributeError + # would be raised because CommonValidateOptions hasn't been called yet. + with self.assertRaises(AttributeError): + _ = opts.verbose + + cmd.CommonValidateOptions(opts, args) + self.assertTrue(hasattr(opts, "verbose"))