diff --git a/google/api_core/client_logging.py b/google/api_core/client_logging.py index fbdde370..bc80e52b 100644 --- a/google/api_core/client_logging.py +++ b/google/api_core/client_logging.py @@ -7,7 +7,7 @@ _LOGGING_INITIALIZED = False _BASE_LOGGER_NAME = "google" -# TODO(https://github.com/googleapis/python-api-core/issues/761): Update this list to support additional logging fields +# TODO(https://github.com/googleapis/python-api-core/issues/761): Update this list to support additional logging fields. _recognized_logging_fields = [ "httpRequest", "rpcName", @@ -50,7 +50,7 @@ def configure_defaults(logger): logger.addHandler(console_handler) -def setup_logging(scopes=[]): +def setup_logging(scopes=""): # only returns valid logger scopes (namespaces) # this list has at most one element. @@ -70,6 +70,8 @@ def setup_logging(scopes=[]): class StructuredLogFormatter(logging.Formatter): + # TODO(https://github.com/googleapis/python-api-core/issues/761): ensure that additional fields such as + # function name, file name, and line no. appear in a log output. def format(self, record): log_obj = { "timestamp": self.formatTime(record), diff --git a/tests/unit/test_client_logging.py b/tests/unit/test_client_logging.py index 66610366..b2467037 100644 --- a/tests/unit/test_client_logging.py +++ b/tests/unit/test_client_logging.py @@ -1,9 +1,11 @@ +import json import logging from unittest import mock from google.api_core.client_logging import ( setup_logging, initialize_logging, + StructuredLogFormatter, ) @@ -28,10 +30,10 @@ def test_setup_logging_w_no_scopes(): def test_setup_logging_w_base_scope(): with mock.patch("google.api_core.client_logging._BASE_LOGGER_NAME", "foo"): setup_logging("foo") - base_logger = logging.getLogger("foo") - assert isinstance(base_logger.handlers[0], logging.StreamHandler) - assert not base_logger.propagate - assert base_logger.level == logging.DEBUG + base_logger = logging.getLogger("foo") + assert isinstance(base_logger.handlers[0], logging.StreamHandler) + assert not base_logger.propagate + assert base_logger.level == logging.DEBUG reset_logger("foo") @@ -40,15 +42,15 @@ def test_setup_logging_w_module_scope(): with mock.patch("google.api_core.client_logging._BASE_LOGGER_NAME", "foo"): setup_logging("foo.bar") - base_logger = logging.getLogger("foo") - assert base_logger.handlers == [] - assert not base_logger.propagate - assert base_logger.level == logging.NOTSET + base_logger = logging.getLogger("foo") + assert base_logger.handlers == [] + assert not base_logger.propagate + assert base_logger.level == logging.NOTSET - module_logger = logging.getLogger("foo.bar") - assert isinstance(module_logger.handlers[0], logging.StreamHandler) - assert not module_logger.propagate - assert module_logger.level == logging.DEBUG + module_logger = logging.getLogger("foo.bar") + assert isinstance(module_logger.handlers[0], logging.StreamHandler) + assert not module_logger.propagate + assert module_logger.level == logging.DEBUG reset_logger("foo") reset_logger("foo.bar") @@ -58,16 +60,16 @@ def test_setup_logging_w_incorrect_scope(): with mock.patch("google.api_core.client_logging._BASE_LOGGER_NAME", "foo"): setup_logging("abc") - base_logger = logging.getLogger("foo") - assert base_logger.handlers == [] - assert not base_logger.propagate - assert base_logger.level == logging.NOTSET + base_logger = logging.getLogger("foo") + assert base_logger.handlers == [] + assert not base_logger.propagate + assert base_logger.level == logging.NOTSET - # TODO(https://github.com/googleapis/python-api-core/issues/759): update test once we add logic to ignore an incorrect scope. - logger = logging.getLogger("abc") - assert isinstance(logger.handlers[0], logging.StreamHandler) - assert not logger.propagate - assert logger.level == logging.DEBUG + # TODO(https://github.com/googleapis/python-api-core/issues/759): update test once we add logic to ignore an incorrect scope. + logger = logging.getLogger("abc") + assert isinstance(logger.handlers[0], logging.StreamHandler) + assert not logger.propagate + assert logger.level == logging.DEBUG reset_logger("foo") reset_logger("abc") @@ -79,25 +81,48 @@ def test_initialize_logging(): with mock.patch("google.api_core.client_logging._BASE_LOGGER_NAME", "foo"): initialize_logging() - base_logger = logging.getLogger("foo") - assert base_logger.handlers == [] - assert not base_logger.propagate - assert base_logger.level == logging.NOTSET + base_logger = logging.getLogger("foo") + assert base_logger.handlers == [] + assert not base_logger.propagate + assert base_logger.level == logging.NOTSET - module_logger = logging.getLogger("foo.bar") - assert isinstance(module_logger.handlers[0], logging.StreamHandler) - assert not module_logger.propagate - assert module_logger.level == logging.DEBUG + module_logger = logging.getLogger("foo.bar") + assert isinstance(module_logger.handlers[0], logging.StreamHandler) + assert not module_logger.propagate + assert module_logger.level == logging.DEBUG - base_logger.propagate = True - module_logger.propagate = True + # Check that `initialize_logging()` is a no-op after the first time by verifying that user-set configs are not modified: + base_logger.propagate = True + module_logger.propagate = True - with mock.patch("os.getenv", return_value="foo.bar"): - with mock.patch("google.api_core.client_logging._BASE_LOGGER_NAME", "foo"): initialize_logging() - assert base_logger.propagate - assert module_logger.propagate + assert base_logger.propagate + assert module_logger.propagate reset_logger("foo") reset_logger("foo.bar") + + +def test_structured_log_formatter(): + # TODO(https://github.com/googleapis/python-api-core/issues/761): Test additional fields when implemented. + record = logging.LogRecord( + name="foo", + level=logging.DEBUG, + msg="This is a test message.", + pathname="foo/bar", + lineno=25, + args=None, + exc_info=None, + ) + + # Extra fields: + record.rpcName = "bar" + + formatted_msg = StructuredLogFormatter().format(record) + parsed_msg = json.loads(formatted_msg) + + assert parsed_msg["name"] == "foo" + assert parsed_msg["severity"] == "DEBUG" + assert parsed_msg["message"] == "This is a test message." + assert parsed_msg["rpcName"] == "bar"