From 319639f123414c576a7b26368f3a70984e1c508b Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 11 Oct 2022 16:27:41 -0700 Subject: [PATCH 1/8] attempt to append extra details to batch log errors --- google/cloud/logging_v2/logger.py | 27 +++++++++++++++++++++++++-- 1 file changed, 25 insertions(+), 2 deletions(-) diff --git a/google/cloud/logging_v2/logger.py b/google/cloud/logging_v2/logger.py index fa0af170c..13e8eac74 100644 --- a/google/cloud/logging_v2/logger.py +++ b/google/cloud/logging_v2/logger.py @@ -15,6 +15,7 @@ """Define API Loggers.""" import collections +import re from google.cloud.logging_v2._helpers import _add_defaults_to_filter from google.cloud.logging_v2.entries import LogEntry @@ -25,6 +26,9 @@ from google.cloud.logging_v2.handlers._monitored_resources import detect_resource from google.cloud.logging_v2._instrumentation import _add_instrumentation +from google.api_core.exceptions import InvalidArgument +from google.rpc.error_details_pb2 import DebugInfo + import google.protobuf.message _GLOBAL_RESOURCE = Resource(type="global", labels={}) @@ -457,6 +461,25 @@ def commit(self, *, client=None): kwargs["labels"] = self.logger.labels entries = [entry.to_api_repr() for entry in self.entries] - - client.logging_api.write_entries(entries, **kwargs) + try: + client.logging_api.write_entries(entries, partial_success=partial_success, **kwargs) + except InvalidArgument as e: + # InvalidArgument is often sent when a log is too large + # attempt to attach extra contex on which log caused error + try: + # find debug info proto if in details + debug_info = next(x for x in e.details if isinstance(x, DebugInfo)) + # parse out the index of the faulty entry + error_idx = re.search('(?<=key: )[0-9]+', debug_info.detail).group(0) + # find the faulty entry object + found_entry = entries[int(error_idx)] + # modify error message to contain extra context + e.message = f"{e.message}: {str(found_entry):.1000}" + if e.metadata is None: + e.metadata = {} + e.metadata["log_entry"] = found_entry + except: + pass + finally: + raise e del self.entries[:] From 86fb0e51ba9fa6be00a517460a00ef8ec9cdef1a Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 11 Oct 2022 17:01:29 -0700 Subject: [PATCH 2/8] refactored into function --- google/cloud/logging_v2/logger.py | 45 +++++++++++++++++++------------ 1 file changed, 28 insertions(+), 17 deletions(-) diff --git a/google/cloud/logging_v2/logger.py b/google/cloud/logging_v2/logger.py index 13e8eac74..e6d584d1c 100644 --- a/google/cloud/logging_v2/logger.py +++ b/google/cloud/logging_v2/logger.py @@ -462,24 +462,35 @@ def commit(self, *, client=None): entries = [entry.to_api_repr() for entry in self.entries] try: - client.logging_api.write_entries(entries, partial_success=partial_success, **kwargs) + client.logging_api.write_entries(entries, partial_success=True, **kwargs) except InvalidArgument as e: # InvalidArgument is often sent when a log is too large # attempt to attach extra contex on which log caused error - try: - # find debug info proto if in details - debug_info = next(x for x in e.details if isinstance(x, DebugInfo)) - # parse out the index of the faulty entry - error_idx = re.search('(?<=key: )[0-9]+', debug_info.detail).group(0) - # find the faulty entry object - found_entry = entries[int(error_idx)] - # modify error message to contain extra context - e.message = f"{e.message}: {str(found_entry):.1000}" - if e.metadata is None: - e.metadata = {} - e.metadata["log_entry"] = found_entry - except: - pass - finally: - raise e + self._append_context_to_error(e) + raise e del self.entries[:] + + def _append_context_to_error(self, err): + """ + Attempts to Modify `write_entries` exception messages to contain + context on which log in the batch caused the error. + + Best-effort basis. If another exception occurs while processing the + input exception, the input will be left unmodified + + Args: + err (~google.api_core.exceptions.InvalidArgument): + The original exception object + """ + try: + # find debug info proto if in details + debug_info = next(x for x in err.details if isinstance(x, DebugInfo)) + # parse out the index of the faulty entry + error_idx = re.search('(?<=key: )[0-9]+', debug_info.detail).group(0) + # find the faulty entry object + found_entry = self.entries[int(error_idx)] + # modify error message to contain extra context + err.message = f"{err.message}: {str(found_entry):.2000}" + except: + # abort changes and leave err unmodified + pass From 0ffbd9549be4ac2c3a047be49d1c7a9a72488f72 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 11 Oct 2022 17:07:16 -0700 Subject: [PATCH 3/8] added ... to indicate truncation --- google/cloud/logging_v2/logger.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/google/cloud/logging_v2/logger.py b/google/cloud/logging_v2/logger.py index e6d584d1c..c45081af3 100644 --- a/google/cloud/logging_v2/logger.py +++ b/google/cloud/logging_v2/logger.py @@ -490,7 +490,7 @@ def _append_context_to_error(self, err): # find the faulty entry object found_entry = self.entries[int(error_idx)] # modify error message to contain extra context - err.message = f"{err.message}: {str(found_entry):.2000}" + err.message = f"{err.message}: {str(found_entry):.2000}..." except: - # abort changes and leave err unmodified + # if parsing fails, abort changes and leave err unmodified pass From 97032e61e6ca315fa410c782cd35c80d857dff28 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 13 Oct 2022 14:50:29 -0700 Subject: [PATCH 4/8] use api_repr; catch Exception --- google/cloud/logging_v2/logger.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/google/cloud/logging_v2/logger.py b/google/cloud/logging_v2/logger.py index c45081af3..b7dc79682 100644 --- a/google/cloud/logging_v2/logger.py +++ b/google/cloud/logging_v2/logger.py @@ -489,8 +489,9 @@ def _append_context_to_error(self, err): error_idx = re.search('(?<=key: )[0-9]+', debug_info.detail).group(0) # find the faulty entry object found_entry = self.entries[int(error_idx)] + str_entry = str(found_entry.to_api_repr()) # modify error message to contain extra context - err.message = f"{err.message}: {str(found_entry):.2000}..." - except: + err.message = f"{err.message}: {str_entry:.2000}..." + except Exception: # if parsing fails, abort changes and leave err unmodified pass From 45d485147481b781cda4c717804fea3f75edfa1f Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 13 Oct 2022 14:50:46 -0700 Subject: [PATCH 5/8] added tests --- tests/unit/test_logger.py | 78 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 78 insertions(+) diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index 539fdcf7b..0559640c0 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -1697,6 +1697,65 @@ def test_context_mgr_failure(self): self.assertEqual(list(batch.entries), UNSENT) self.assertIsNone(api._write_entries_called_with) + def test_append_context_to_error(self): + """ + If an InvalidArgument exception contains info on the log that threw it, + we should be able to add it to the exceptiom message. If not, the + exception should be unchanged + """ + from google.api_core.exceptions import InvalidArgument + from google.rpc.error_details_pb2 import DebugInfo + from google.cloud.logging import TextEntry + logger = _Logger() + client = _Client(project=self.PROJECT) + batch = self._make_one(logger, client=client) + test_entries = [TextEntry(payload=str(i)) for i in range(11)] + batch.entries = test_entries + starting_message = "test" + # test that properly formatted exceptions add log details + for idx, entry in enumerate(test_entries): + api_entry = entry.to_api_repr() + err = InvalidArgument(starting_message, + details=["padding", DebugInfo(detail=f"key: {idx}")]) + batch._append_context_to_error(err) + self.assertEqual(err.message, f"{starting_message}: {str(api_entry)}...") + self.assertIn(str(idx), str(entry)) + # test with missing debug info + err = InvalidArgument(starting_message, details=[]) + batch._append_context_to_error(err) + self.assertEqual(err.message, starting_message, "message should have been unchanged") + # test with missing key + err = InvalidArgument(starting_message, + details=["padding", DebugInfo(detail=f"no k e y here")]) + batch._append_context_to_error(err) + self.assertEqual(err.message, starting_message, "message should have been unchanged") + # test with key out of range + err = InvalidArgument(starting_message, + details=["padding", DebugInfo(detail=f"key: 100")]) + batch._append_context_to_error(err) + self.assertEqual(err.message, starting_message, "message should have been unchanged") + + def test_batch_error_gets_context(self): + """ + Simulate an InvalidArgument sent as part of a batch commit, to ensure + _append_context_to_error is thrown + """ + from google.api_core.exceptions import InvalidArgument + from google.rpc.error_details_pb2 import DebugInfo + from google.cloud.logging import TextEntry + logger = _Logger() + client = _Client(project=self.PROJECT) + starting_message = "hello" + exception = InvalidArgument(starting_message, details=[DebugInfo(detail=f"key: 1")]) + client.logging_api = _DummyLoggingExceptionAPI(exception) + batch = self._make_one(logger, client=client) + test_entries = [TextEntry(payload=str(i)) for i in range(11)] + batch.entries = test_entries + with self.assertRaises(InvalidArgument) as e: + batch.commit() + expected_log = test_entries[1] + api_entry = expected_log.to_api_repr() + self.assertEqual(e.message, f"{starting_message}: {str(api_entry)}...") class _Logger(object): @@ -1725,6 +1784,25 @@ def logger_delete(self, logger_name): self._logger_delete_called_with = logger_name +class _DummyLoggingExceptionAPI(object): + + def __init__(self, exception): + self.exception = exception + + def write_entries( + self, + entries, + *, + logger_name=None, + resource=None, + labels=None, + partial_success=False, + ): + raise self.exception + + def logger_delete(self, logger_name): + raise self.exception + class _Client(object): def __init__(self, project, connection=None): self.project = project From ce9020d6b2b63455c7ca3ed5ac135bd872beac90 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 13 Oct 2022 14:51:29 -0700 Subject: [PATCH 6/8] blacken --- google/cloud/logging_v2/logger.py | 2 +- tests/unit/test_logger.py | 36 +++++++++++++++++++++---------- 2 files changed, 26 insertions(+), 12 deletions(-) diff --git a/google/cloud/logging_v2/logger.py b/google/cloud/logging_v2/logger.py index b7dc79682..15476ce15 100644 --- a/google/cloud/logging_v2/logger.py +++ b/google/cloud/logging_v2/logger.py @@ -486,7 +486,7 @@ def _append_context_to_error(self, err): # find debug info proto if in details debug_info = next(x for x in err.details if isinstance(x, DebugInfo)) # parse out the index of the faulty entry - error_idx = re.search('(?<=key: )[0-9]+', debug_info.detail).group(0) + error_idx = re.search("(?<=key: )[0-9]+", debug_info.detail).group(0) # find the faulty entry object found_entry = self.entries[int(error_idx)] str_entry = str(found_entry.to_api_repr()) diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index 0559640c0..1674ec1f6 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -1706,6 +1706,7 @@ def test_append_context_to_error(self): from google.api_core.exceptions import InvalidArgument from google.rpc.error_details_pb2 import DebugInfo from google.cloud.logging import TextEntry + logger = _Logger() client = _Client(project=self.PROJECT) batch = self._make_one(logger, client=client) @@ -1715,25 +1716,34 @@ def test_append_context_to_error(self): # test that properly formatted exceptions add log details for idx, entry in enumerate(test_entries): api_entry = entry.to_api_repr() - err = InvalidArgument(starting_message, - details=["padding", DebugInfo(detail=f"key: {idx}")]) + err = InvalidArgument( + starting_message, details=["padding", DebugInfo(detail=f"key: {idx}")] + ) batch._append_context_to_error(err) self.assertEqual(err.message, f"{starting_message}: {str(api_entry)}...") self.assertIn(str(idx), str(entry)) # test with missing debug info err = InvalidArgument(starting_message, details=[]) batch._append_context_to_error(err) - self.assertEqual(err.message, starting_message, "message should have been unchanged") + self.assertEqual( + err.message, starting_message, "message should have been unchanged" + ) # test with missing key - err = InvalidArgument(starting_message, - details=["padding", DebugInfo(detail=f"no k e y here")]) + err = InvalidArgument( + starting_message, details=["padding", DebugInfo(detail=f"no k e y here")] + ) batch._append_context_to_error(err) - self.assertEqual(err.message, starting_message, "message should have been unchanged") + self.assertEqual( + err.message, starting_message, "message should have been unchanged" + ) # test with key out of range - err = InvalidArgument(starting_message, - details=["padding", DebugInfo(detail=f"key: 100")]) + err = InvalidArgument( + starting_message, details=["padding", DebugInfo(detail=f"key: 100")] + ) batch._append_context_to_error(err) - self.assertEqual(err.message, starting_message, "message should have been unchanged") + self.assertEqual( + err.message, starting_message, "message should have been unchanged" + ) def test_batch_error_gets_context(self): """ @@ -1743,10 +1753,13 @@ def test_batch_error_gets_context(self): from google.api_core.exceptions import InvalidArgument from google.rpc.error_details_pb2 import DebugInfo from google.cloud.logging import TextEntry + logger = _Logger() client = _Client(project=self.PROJECT) starting_message = "hello" - exception = InvalidArgument(starting_message, details=[DebugInfo(detail=f"key: 1")]) + exception = InvalidArgument( + starting_message, details=[DebugInfo(detail=f"key: 1")] + ) client.logging_api = _DummyLoggingExceptionAPI(exception) batch = self._make_one(logger, client=client) test_entries = [TextEntry(payload=str(i)) for i in range(11)] @@ -1757,6 +1770,7 @@ def test_batch_error_gets_context(self): api_entry = expected_log.to_api_repr() self.assertEqual(e.message, f"{starting_message}: {str(api_entry)}...") + class _Logger(object): labels = None @@ -1785,7 +1799,6 @@ def logger_delete(self, logger_name): class _DummyLoggingExceptionAPI(object): - def __init__(self, exception): self.exception = exception @@ -1803,6 +1816,7 @@ def write_entries( def logger_delete(self, logger_name): raise self.exception + class _Client(object): def __init__(self, project, connection=None): self.project = project From 1fdf027bcbea7e8126f2b2a58e22a1ef5f8fc970 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Mon, 17 Oct 2022 13:16:00 -0700 Subject: [PATCH 7/8] skup tests on python 3.7 --- tests/unit/test_logger.py | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index 42416ca2f..ae7008b3b 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -16,8 +16,10 @@ from datetime import datetime from datetime import timedelta from datetime import timezone +import sys import unittest +import pytest import mock @@ -1739,6 +1741,10 @@ def test_context_mgr_failure(self): self.assertEqual(list(batch.entries), UNSENT) self.assertIsNone(api._write_entries_called_with) + @pytest.mark.skipif( + sys.version_info < (3, 8), + reason="InvalidArgument init with details requires python3.8+", + ) def test_append_context_to_error(self): """ If an InvalidArgument exception contains info on the log that threw it, @@ -1787,6 +1793,10 @@ def test_append_context_to_error(self): err.message, starting_message, "message should have been unchanged" ) + @pytest.mark.skipif( + sys.version_info < (3, 8), + reason="InvalidArgument init with details requires python3.8+", + ) def test_batch_error_gets_context(self): """ Simulate an InvalidArgument sent as part of a batch commit, to ensure From 1f92fa8b31222501b23ec0aca6d84509f4a0a2f5 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Mon, 17 Oct 2022 15:28:33 -0700 Subject: [PATCH 8/8] removed fstrings --- tests/unit/test_logger.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index ae7008b3b..3091693e3 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -1778,7 +1778,7 @@ def test_append_context_to_error(self): ) # test with missing key err = InvalidArgument( - starting_message, details=["padding", DebugInfo(detail=f"no k e y here")] + starting_message, details=["padding", DebugInfo(detail="no k e y here")] ) batch._append_context_to_error(err) self.assertEqual( @@ -1786,7 +1786,7 @@ def test_append_context_to_error(self): ) # test with key out of range err = InvalidArgument( - starting_message, details=["padding", DebugInfo(detail=f"key: 100")] + starting_message, details=["padding", DebugInfo(detail="key: 100")] ) batch._append_context_to_error(err) self.assertEqual( @@ -1810,7 +1810,7 @@ def test_batch_error_gets_context(self): client = _Client(project=self.PROJECT) starting_message = "hello" exception = InvalidArgument( - starting_message, details=[DebugInfo(detail=f"key: 1")] + starting_message, details=[DebugInfo(detail="key: 1")] ) client.logging_api = _DummyLoggingExceptionAPI(exception) batch = self._make_one(logger, client=client)