From 2df593a194a959c056b56767e607be6e1a13a5a2 Mon Sep 17 00:00:00 2001 From: Tres Seaver Date: Tue, 30 Jul 2019 17:59:28 -0400 Subject: [PATCH 1/7] Add '_helpers._normalize_severity'. Converts Python stdlb log levels to Stackdriver severity values. --- logging/google/cloud/logging/_helpers.py | 41 ++++++++++++++++++++++ logging/tests/unit/test__helpers.py | 44 ++++++++++++++++++++++++ 2 files changed, 85 insertions(+) diff --git a/logging/google/cloud/logging/_helpers.py b/logging/google/cloud/logging/_helpers.py index ed7a0ba8cf7b..4df8b12736bc 100644 --- a/logging/google/cloud/logging/_helpers.py +++ b/logging/google/cloud/logging/_helpers.py @@ -14,6 +14,8 @@ """Common logging helpers.""" +import logging + import requests from google.cloud.logging.entries import LogEntry @@ -21,6 +23,33 @@ from google.cloud.logging.entries import StructEntry from google.cloud.logging.entries import TextEntry +try: + from google.cloud.logging_v2.gapic.enums import LogSeverity +except ImportError: # pragma: NO COVER + + class LogSeverity(object): + """Map severities for non-GAPIC usage.""" + + DEFAULT = 0 + DEBUG = 100 + INFO = 200 + NOTICE = 300 + WARNING = 400 + ERROR = 500 + CRITICAL = 600 + ALERT = 700 + EMERGENCY = 800 + + +_NORMALIZED_SEVERITIES = { + logging.CRITICAL: LogSeverity.CRITICAL, + logging.ERROR: LogSeverity.ERROR, + logging.WARNING: LogSeverity.WARNING, + logging.INFO: LogSeverity.INFO, + logging.DEBUG: LogSeverity.DEBUG, + logging.NOTSET: LogSeverity.DEFAULT, +} + METADATA_URL = "http://metadata.google.internal./computeMetadata/v1/" METADATA_HEADERS = {"Metadata-Flavor": "Google"} @@ -82,3 +111,15 @@ def retrieve_metadata_server(metadata_key): pass return None + + +def _normalize_severity(stdlib_level): + """Normalize a Python stdlib severity to LogSeverity enum. + + :type stdlib_level: int + :param stdlib_level: 'levelno' from a :class:`logging.LogRecord` + + :rtype: int + :returns: Corresponding Stackdriver severity. + """ + return _NORMALIZED_SEVERITIES.get(stdlib_level, stdlib_level) diff --git a/logging/tests/unit/test__helpers.py b/logging/tests/unit/test__helpers.py index 7f11988f5275..7044254e46af 100644 --- a/logging/tests/unit/test__helpers.py +++ b/logging/tests/unit/test__helpers.py @@ -13,10 +13,13 @@ # limitations under the License. +import logging import unittest import mock +from google.cloud.logging_v2.gapic.enums import LogSeverity + class Test_entry_from_resource(unittest.TestCase): @staticmethod @@ -121,6 +124,47 @@ def test_request_exception(self): self.assertIsNone(metadata) +class Test__normalize_severity(unittest.TestCase): + @staticmethod + def _stackdriver_severity(): + from google.cloud.logging._helpers import LogSeverity + + return LogSeverity + + def _normalize_severity_helper(self, stdlib_level, enum_level): + from google.cloud.logging._helpers import _normalize_severity + + self.assertEqual(_normalize_severity(stdlib_level), enum_level) + + def test__normalize_severity_critical(self): + severity = self._stackdriver_severity() + self._normalize_severity_helper(logging.CRITICAL, severity.CRITICAL) + + def test__normalize_severity_error(self): + severity = self._stackdriver_severity() + self._normalize_severity_helper(logging.ERROR, severity.ERROR) + + def test__normalize_severity_warning(self): + severity = self._stackdriver_severity() + self._normalize_severity_helper(logging.WARNING, severity.WARNING) + + def test__normalize_severity_info(self): + severity = self._stackdriver_severity() + self._normalize_severity_helper(logging.INFO, severity.INFO) + + def test__normalize_severity_debug(self): + severity = self._stackdriver_severity() + self._normalize_severity_helper(logging.DEBUG, severity.DEBUG) + + def test__normalize_severity_notset(self): + severity = self._stackdriver_severity() + self._normalize_severity_helper(logging.NOTSET, severity.DEFAULT) + + def test__normalize_severity_non_standard(self): + unknown_level = 35 + self._normalize_severity_helper(unknown_level, unknown_level) + + class EntryMock(object): def __init__(self): self.sentinel = object() From 87d6885f68e4f470bff1fc2dc99a73dfab83f989 Mon Sep 17 00:00:00 2001 From: Tres Seaver Date: Tue, 30 Jul 2019 18:25:50 -0400 Subject: [PATCH 2/7] Normalize stdlib levelno to Stackdriver severity. Closes #7213. --- .../handlers/transports/background_thread.py | 22 +++---- .../cloud/logging/handlers/transports/sync.py | 3 +- .../transports/test_background_thread.py | 60 +++++++++++++++++-- .../unit/handlers/transports/test_sync.py | 10 +++- 4 files changed, 78 insertions(+), 17 deletions(-) diff --git a/logging/google/cloud/logging/handlers/transports/background_thread.py b/logging/google/cloud/logging/handlers/transports/background_thread.py index be7710ab1479..812b733cff92 100644 --- a/logging/google/cloud/logging/handlers/transports/background_thread.py +++ b/logging/google/cloud/logging/handlers/transports/background_thread.py @@ -28,6 +28,7 @@ from six.moves import queue +from google.cloud.logging import _helpers from google.cloud.logging.handlers.transports.base import Transport _DEFAULT_GRACE_PERIOD = 5.0 # Seconds @@ -254,17 +255,16 @@ def enqueue( :param span_id: (optional) span_id within the trace for the log entry. Specify the trace parameter if span_id is set. """ - self._queue.put_nowait( - { - "info": {"message": message, "python_logger": record.name}, - "severity": record.levelname, - "resource": resource, - "labels": labels, - "trace": trace, - "span_id": span_id, - "timestamp": datetime.datetime.utcfromtimestamp(record.created), - } - ) + queue_entry = { + "info": {"message": message, "python_logger": record.name}, + "severity": _helpers._normalize_severity(record.levelno), + "resource": resource, + "labels": labels, + "trace": trace, + "span_id": span_id, + "timestamp": datetime.datetime.utcfromtimestamp(record.created), + } + self._queue.put_nowait(queue_entry) def flush(self): """Submit any pending log records.""" diff --git a/logging/google/cloud/logging/handlers/transports/sync.py b/logging/google/cloud/logging/handlers/transports/sync.py index 861f1ab3fdf7..e87eb4885fbf 100644 --- a/logging/google/cloud/logging/handlers/transports/sync.py +++ b/logging/google/cloud/logging/handlers/transports/sync.py @@ -17,6 +17,7 @@ Logs directly to the the Stackdriver Logging API with a synchronous call. """ +from google.cloud.logging import _helpers from google.cloud.logging.handlers.transports.base import Transport @@ -50,7 +51,7 @@ def send( info = {"message": message, "python_logger": record.name} self.logger.log_struct( info, - severity=record.levelname, + severity=_helpers._normalize_severity(record.levelno), resource=resource, labels=labels, trace=trace, diff --git a/logging/tests/unit/handlers/transports/test_background_thread.py b/logging/tests/unit/handlers/transports/test_background_thread.py index 717fb1ffc9d9..f63efda9bbd6 100644 --- a/logging/tests/unit/handlers/transports/test_background_thread.py +++ b/logging/tests/unit/handlers/transports/test_background_thread.py @@ -264,13 +264,65 @@ def test__main_thread_terminated_did_not_join(self): self.assertFalse(worker.is_alive) @staticmethod - def _enqueue_record(worker, message): - record = logging.LogRecord( - "python_logger", logging.INFO, None, None, message, None, None + def _enqueue_record(worker, message, levelno=logging.INFO, **kw): + record = logging.LogRecord("testing", levelno, None, None, message, None, None) + worker.enqueue(record, message, **kw) + + def test_enqueue_defaults(self): + import datetime + from google.cloud.logging._helpers import LogSeverity + + worker = self._make_one(_Logger(self.NAME)) + self.assertTrue(worker._queue.empty()) + message = "TEST SEVERITY" + + self._enqueue_record(worker, message) + + entry = worker._queue.get_nowait() + expected_info = {"message": message, "python_logger": "testing"} + self.assertEqual(entry["info"], expected_info) + self.assertEqual(entry["severity"], LogSeverity.INFO) + self.assertIsNone(entry["resource"]) + self.assertIsNone(entry["labels"]) + self.assertIsNone(entry["trace"]) + self.assertIsNone(entry["span_id"]) + self.assertIsInstance(entry["timestamp"], datetime.datetime) + + def test_enqueue_explicit(self): + import datetime + from google.cloud.logging._helpers import LogSeverity + + worker = self._make_one(_Logger(self.NAME)) + self.assertTrue(worker._queue.empty()) + message = "TEST SEVERITY" + resource = object() + labels = {"foo": "bar"} + trace = "TRACE" + span_id = "SPAN_ID" + + self._enqueue_record( + worker, + message, + levelno=logging.ERROR, + resource=resource, + labels=labels, + trace=trace, + span_id=span_id, ) - worker.enqueue(record, message) + + entry = worker._queue.get_nowait() + + expected_info = {"message": message, "python_logger": "testing"} + self.assertEqual(entry["info"], expected_info) + self.assertEqual(entry["severity"], LogSeverity.ERROR) + self.assertIs(entry["resource"], resource) + self.assertIs(entry["labels"], labels) + self.assertIs(entry["trace"], trace) + self.assertIs(entry["span_id"], span_id) + self.assertIsInstance(entry["timestamp"], datetime.datetime) def test__thread_main(self): + import datetime from google.cloud.logging.handlers.transports import background_thread worker = self._make_one(_Logger(self.NAME)) diff --git a/logging/tests/unit/handlers/transports/test_sync.py b/logging/tests/unit/handlers/transports/test_sync.py index ca6e9260c7a1..f2ff67d59d82 100644 --- a/logging/tests/unit/handlers/transports/test_sync.py +++ b/logging/tests/unit/handlers/transports/test_sync.py @@ -37,6 +37,7 @@ def test_ctor(self): def test_send(self): from google.cloud.logging.logger import _GLOBAL_RESOURCE + from google.cloud.logging._helpers import LogSeverity client = _Client(self.PROJECT) @@ -50,7 +51,14 @@ def test_send(self): transport.send(record, message, _GLOBAL_RESOURCE) EXPECTED_STRUCT = {"message": message, "python_logger": python_logger_name} - EXPECTED_SENT = (EXPECTED_STRUCT, "INFO", _GLOBAL_RESOURCE, None, None, None) + EXPECTED_SENT = ( + EXPECTED_STRUCT, + LogSeverity.INFO, + _GLOBAL_RESOURCE, + None, + None, + None, + ) self.assertEqual(transport.logger.log_struct_called_with, EXPECTED_SENT) From 3fa867261d977c7a375245e6e598b2a4c011ef40 Mon Sep 17 00:00:00 2001 From: Tres Seaver Date: Tue, 30 Jul 2019 22:37:51 -0400 Subject: [PATCH 3/7] Remove spurious import. --- logging/tests/unit/handlers/transports/test_background_thread.py | 1 - 1 file changed, 1 deletion(-) diff --git a/logging/tests/unit/handlers/transports/test_background_thread.py b/logging/tests/unit/handlers/transports/test_background_thread.py index f63efda9bbd6..7de912560aa7 100644 --- a/logging/tests/unit/handlers/transports/test_background_thread.py +++ b/logging/tests/unit/handlers/transports/test_background_thread.py @@ -322,7 +322,6 @@ def test_enqueue_explicit(self): self.assertIsInstance(entry["timestamp"], datetime.datetime) def test__thread_main(self): - import datetime from google.cloud.logging.handlers.transports import background_thread worker = self._make_one(_Logger(self.NAME)) From df2702de4660a03a9ce91c6cc9a8a2805e7346a2 Mon Sep 17 00:00:00 2001 From: Tres Seaver Date: Wed, 31 Jul 2019 13:11:09 -0400 Subject: [PATCH 4/7] Remove stray import. --- logging/tests/unit/test__helpers.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/logging/tests/unit/test__helpers.py b/logging/tests/unit/test__helpers.py index 7044254e46af..db0804e66638 100644 --- a/logging/tests/unit/test__helpers.py +++ b/logging/tests/unit/test__helpers.py @@ -18,8 +18,6 @@ import mock -from google.cloud.logging_v2.gapic.enums import LogSeverity - class Test_entry_from_resource(unittest.TestCase): @staticmethod From 1d335c6df9f8b1a18ea756c8a979e1299e6ff400 Mon Sep 17 00:00:00 2001 From: Tres Seaver Date: Wed, 31 Jul 2019 13:14:17 -0400 Subject: [PATCH 5/7] Avoid flaking for NotFound in systest tearDown. --- logging/tests/system/test_system.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/logging/tests/system/test_system.py b/logging/tests/system/test_system.py index 63add9f26fcf..384f2d9d8e64 100644 --- a/logging/tests/system/test_system.py +++ b/logging/tests/system/test_system.py @@ -112,6 +112,8 @@ def tearDown(self): except AttributeError: client, dataset = doomed retry(client.delete_dataset)(dataset) + except NotFound: + pass logging.getLogger().handlers = self._handlers_cache[:] @staticmethod From c8b7c02b91b5e5c82bcad6ac91c4a5370381ca49 Mon Sep 17 00:00:00 2001 From: Tres Seaver Date: Wed, 31 Jul 2019 13:24:59 -0400 Subject: [PATCH 6/7] Refactor retry handling for tearDown. Avoid excessive retries for NotFound. --- logging/tests/system/test_system.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/logging/tests/system/test_system.py b/logging/tests/system/test_system.py index 384f2d9d8e64..23cf0157b99a 100644 --- a/logging/tests/system/test_system.py +++ b/logging/tests/system/test_system.py @@ -105,10 +105,11 @@ def setUp(self): self._handlers_cache = logging.getLogger().handlers[:] def tearDown(self): - retry = RetryErrors((NotFound, TooManyRequests, RetryError), max_tries=9) + retry_not_found = RetryErrors((NotFound), max_tries=4) + retry_other = RetryErrors((TooManyRequests, RetryError)) for doomed in self.to_delete: try: - retry(doomed.delete)() + retry_not_found(retry_other(doomed.delete))() except AttributeError: client, dataset = doomed retry(client.delete_dataset)(dataset) From ceb3fbc14d50361cd147dd81bc1f786c7681f94f Mon Sep 17 00:00:00 2001 From: Tres Seaver Date: Wed, 31 Jul 2019 15:37:00 -0400 Subject: [PATCH 7/7] Grrrr. --- logging/tests/system/test_system.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/logging/tests/system/test_system.py b/logging/tests/system/test_system.py index 23cf0157b99a..8e2d694081a1 100644 --- a/logging/tests/system/test_system.py +++ b/logging/tests/system/test_system.py @@ -112,7 +112,7 @@ def tearDown(self): retry_not_found(retry_other(doomed.delete))() except AttributeError: client, dataset = doomed - retry(client.delete_dataset)(dataset) + retry_not_found(retry_other(client.delete_dataset))(dataset) except NotFound: pass logging.getLogger().handlers = self._handlers_cache[:]