From 42c163bf86e5de488b3255d4ed9e7ad0a1f13579 Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Fri, 21 Jul 2023 11:36:16 +0100 Subject: [PATCH 01/11] 602 Introduce str logging --- mlserver/logging.py | 44 ++++++++++++++++++++++++++++++++++++------ mlserver/settings.py | 2 ++ tests/test_logging.py | 45 ++++++++++++++++++++++++++++++++++++++++--- 3 files changed, 82 insertions(+), 9 deletions(-) diff --git a/mlserver/logging.py b/mlserver/logging.py index c19158da6..98694074a 100644 --- a/mlserver/logging.py +++ b/mlserver/logging.py @@ -11,7 +11,6 @@ from .settings import Settings LoggerName = "mlserver" -LoggerFormat = "%(asctime)s [%(name)s]%(model)s %(levelname)s - %(message)s" logger = logging.getLogger(LoggerName) @@ -42,18 +41,46 @@ class ModelLoggerFormatter(logging.Formatter): the model name and version in the log message. """ + _UNSTRUCTURED_FORMAT = "%(asctime)s [%(name)s]%(model)s %(levelname)s - %(message)s" + _STRUCTURED_FORMAT = "{'time':'%(asctime)s', 'name': '%(name)s', 'level': '%(levelname)s', 'message': '%(message)s' %(model)s}" + + def __init__(self, use_structured_logging: bool): + super().__init__( + self._STRUCTURED_FORMAT + if use_structured_logging + else self._UNSTRUCTURED_FORMAT + ) + self.use_structured_logging = use_structured_logging + @staticmethod - def _fmt_model(name: str, version: str) -> str: + def _format_unstructured_model_details(name: str, version: str) -> str: if not name: return "" - model_fmt = f"{name}:{version}" if version else name - return f"[{model_fmt}]" + elif not version: + return f"[{name}]" + else: + return f"[{name}:{version}]" + + @staticmethod + def _format_structured_model_details(name: str, version: str) -> str: + if not name: + return "" + model_details = [] + model_details.append(f"'model_name': {name}") + print() + if version: + model_details += f',"model_version": "{version}"' + return model_details def format(self, record: logging.LogRecord) -> str: model_name = model_name_var.get("") model_version = model_version_var.get("") - record.model = self._fmt_model(model_name, model_version) + record.model = ( + self._format_structured_model_details(model_name, model_version) + if self.use_structured_logging + else self._format_unstructured_model_details(model_name, model_version) + ) return super().format(record) @@ -64,7 +91,12 @@ def configure_logger(settings: Optional[Settings] = None): # Don't add handler twice if not logger.handlers: stream_handler = StreamHandler(sys.stdout) - formatter = ModelLoggerFormatter(LoggerFormat) + + use_structured_logging = False + if settings and settings.use_structured_logging: + use_structured_logging = True + + formatter = ModelLoggerFormatter(use_structured_logging) stream_handler.setFormatter(formatter) logger.addHandler(stream_handler) diff --git a/mlserver/settings.py b/mlserver/settings.py index 41fc90fa8..65f1e48a2 100644 --- a/mlserver/settings.py +++ b/mlserver/settings.py @@ -221,6 +221,8 @@ class Config: """ # Logging settings + use_structured_logging: bool = False + """""" logging_settings: Optional[Union[str, Dict]] = None """Path to logging config file or dictionary configuration.""" diff --git a/tests/test_logging.py b/tests/test_logging.py index f315dd96e..94b065f6b 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -1,10 +1,11 @@ +import json + import pytest from mlserver import ModelSettings from mlserver.context import model_context from mlserver.logging import ( ModelLoggerFormatter, - LoggerFormat, configure_logger, logger, ) @@ -33,8 +34,8 @@ ), ], ) -def test_model_logging_formatter(name, version, expected_fmt, caplog): - caplog.handler.setFormatter(ModelLoggerFormatter(LoggerFormat)) +def test_model_logging_formatter_unstructured(name, version, expected_fmt, caplog): + caplog.handler.setFormatter(ModelLoggerFormatter(use_structured_logging=False)) caplog.set_level(INFO) model_settings = ModelSettings( @@ -54,6 +55,44 @@ def test_model_logging_formatter(name, version, expected_fmt, caplog): assert expected_fmt not in log_records[2] +@pytest.mark.parametrize( + "name, version, expected_fmt", + [ + ( + "foo", + "v1.0", + "{}", + ), + # ( + # "foo", + # "", + # "[foo]", + # ), + # ( + # "foo", + # None, + # "[foo]", + # ), + ], +) +def test_model_logging_formatter_structured(name, version, expected_fmt, caplog): + caplog.handler.setFormatter(ModelLoggerFormatter(use_structured_logging=True)) + caplog.set_level(INFO) + + model_settings = ModelSettings( + name=name, implementation=SumModel, parameters=ModelParameters(version=version) + ) + + logger.info("Before model context") + with model_context(model_settings): + logger.info("Inside model context") + logger.info("After model context") + + structured_log = json.loads(caplog.text) + + assert "model_name" in structured_log + + @pytest.mark.parametrize("debug", [True, False]) def test_log_level_gets_persisted(debug: bool, settings: Settings, caplog): settings.debug = debug From 6941b10ba5d59200f939c2126ad6e227e247c43e Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Fri, 21 Jul 2023 13:22:28 +0100 Subject: [PATCH 02/11] Verify structured logging format for model details --- mlserver/logging.py | 10 +++++----- tests/test_logging.py | 37 +++++++++++++++++++++---------------- 2 files changed, 26 insertions(+), 21 deletions(-) diff --git a/mlserver/logging.py b/mlserver/logging.py index 98694074a..a02af6178 100644 --- a/mlserver/logging.py +++ b/mlserver/logging.py @@ -42,7 +42,9 @@ class ModelLoggerFormatter(logging.Formatter): """ _UNSTRUCTURED_FORMAT = "%(asctime)s [%(name)s]%(model)s %(levelname)s - %(message)s" - _STRUCTURED_FORMAT = "{'time':'%(asctime)s', 'name': '%(name)s', 'level': '%(levelname)s', 'message': '%(message)s' %(model)s}" + _STRUCTURED_FORMAT = "{\"time\":\"%(asctime)s\", \"name\": \"%(name)s\", " \ + "\"level\": \"%(levelname)s\", \"message\": \"%(message)s\"" \ + " %(model)s}" def __init__(self, use_structured_logging: bool): super().__init__( @@ -65,11 +67,9 @@ def _format_unstructured_model_details(name: str, version: str) -> str: def _format_structured_model_details(name: str, version: str) -> str: if not name: return "" - model_details = [] - model_details.append(f"'model_name': {name}") - print() + model_details = f", \"model_name\": \"{name}\"" if version: - model_details += f',"model_version": "{version}"' + model_details += f", \"model_version\": \"{version}\"" return model_details def format(self, record: logging.LogRecord) -> str: diff --git a/tests/test_logging.py b/tests/test_logging.py index 94b065f6b..6b04ffb08 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -48,7 +48,7 @@ def test_model_logging_formatter_unstructured(name, version, expected_fmt, caplo logger.info("After model context") log_records = caplog.text.strip().split("\n") - assert len(caplog.messages) == 3 + assert len(log_records) == 3 assert expected_fmt not in log_records[0] assert expected_fmt in log_records[1] @@ -56,26 +56,26 @@ def test_model_logging_formatter_unstructured(name, version, expected_fmt, caplo @pytest.mark.parametrize( - "name, version, expected_fmt", + "name, version, expected_model_details", [ ( "foo", "v1.0", - "{}", + {"model_name", "model_version"} + ), + ( + "foo", + "", + {"model_name"} + ), + ( + "foo", + None, + {"model_name"} ), - # ( - # "foo", - # "", - # "[foo]", - # ), - # ( - # "foo", - # None, - # "[foo]", - # ), ], ) -def test_model_logging_formatter_structured(name, version, expected_fmt, caplog): +def test_model_logging_formatter_structured(name, version, expected_model_details, caplog): caplog.handler.setFormatter(ModelLoggerFormatter(use_structured_logging=True)) caplog.set_level(INFO) @@ -88,9 +88,14 @@ def test_model_logging_formatter_structured(name, version, expected_fmt, caplog) logger.info("Inside model context") logger.info("After model context") - structured_log = json.loads(caplog.text) + log_records = caplog.text.strip().split("\n") + assert len(log_records) == 3 + + json_log_records = [json.loads(lr) for lr in log_records] - assert "model_name" in structured_log + assert not expected_model_details <= json_log_records[0].keys() + assert expected_model_details <= json_log_records[1].keys() + assert not expected_model_details <= json_log_records[2].keys() @pytest.mark.parametrize("debug", [True, False]) From e5c3140e3c8507db3665f85ce17b0730ec2f6bb2 Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Fri, 21 Jul 2023 14:18:09 +0100 Subject: [PATCH 03/11] Add settings flag explanation --- mlserver/settings.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/mlserver/settings.py b/mlserver/settings.py index 65f1e48a2..430a3033e 100644 --- a/mlserver/settings.py +++ b/mlserver/settings.py @@ -222,7 +222,7 @@ class Config: # Logging settings use_structured_logging: bool = False - """""" + """Use JSON-formatted structured logging instead of default human-readable format.""" logging_settings: Optional[Union[str, Dict]] = None """Path to logging config file or dictionary configuration.""" From 56ae4f179a6eaa120c4d0376d14f4dec606712bb Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Fri, 21 Jul 2023 14:21:02 +0100 Subject: [PATCH 04/11] Refactor formatter docstr and varsd --- mlserver/context.py | 12 ++++++------ mlserver/logging.py | 11 ++++------- mlserver/metrics/context.py | 6 +++--- tests/test_context.py | 14 +++++++------- 4 files changed, 20 insertions(+), 23 deletions(-) diff --git a/mlserver/context.py b/mlserver/context.py index 81d8fa1a9..99c49471f 100644 --- a/mlserver/context.py +++ b/mlserver/context.py @@ -3,21 +3,21 @@ from .settings import ModelSettings -model_name_var: ContextVar[str] = ContextVar("model_name") -model_version_var: ContextVar[str] = ContextVar("model_version") +MODEL_NAME_VAR: ContextVar[str] = ContextVar("model_name") +MODEL_VERSION_VAR: ContextVar[str] = ContextVar("model_version") @contextmanager def model_context(model_settings: ModelSettings): - model_name_token = model_name_var.set(model_settings.name) + model_name_token = MODEL_NAME_VAR.set(model_settings.name) model_version = "" if model_settings.version: model_version = model_settings.version - model_version_token = model_version_var.set(model_version) + model_version_token = MODEL_VERSION_VAR.set(model_version) try: yield finally: - model_name_var.reset(model_name_token) - model_version_var.reset(model_version_token) + MODEL_NAME_VAR.reset(model_name_token) + MODEL_VERSION_VAR.reset(model_version_token) diff --git a/mlserver/logging.py b/mlserver/logging.py index a02af6178..4e999ae12 100644 --- a/mlserver/logging.py +++ b/mlserver/logging.py @@ -7,7 +7,7 @@ from typing import Optional, Dict, Union import logging.config -from .context import model_name_var, model_version_var +from .context import MODEL_NAME_VAR, MODEL_VERSION_VAR from .settings import Settings LoggerName = "mlserver" @@ -36,10 +36,7 @@ def apply_logging_file(logging_settings: Union[str, Dict]): class ModelLoggerFormatter(logging.Formatter): - """ - A logging formatter that uses context variables to inject - the model name and version in the log message. - """ + """Log formatter incorporating model details, e.g. name and version.""" _UNSTRUCTURED_FORMAT = "%(asctime)s [%(name)s]%(model)s %(levelname)s - %(message)s" _STRUCTURED_FORMAT = "{\"time\":\"%(asctime)s\", \"name\": \"%(name)s\", " \ @@ -73,8 +70,8 @@ def _format_structured_model_details(name: str, version: str) -> str: return model_details def format(self, record: logging.LogRecord) -> str: - model_name = model_name_var.get("") - model_version = model_version_var.get("") + model_name = MODEL_NAME_VAR.get("") + model_version = MODEL_VERSION_VAR.get("") record.model = ( self._format_structured_model_details(model_name, model_version) diff --git a/mlserver/metrics/context.py b/mlserver/metrics/context.py index ccb828c11..3b58f17fe 100644 --- a/mlserver/metrics/context.py +++ b/mlserver/metrics/context.py @@ -2,7 +2,7 @@ from .registry import REGISTRY from .errors import InvalidModelContext -from ..context import model_name_var, model_version_var +from ..context import MODEL_NAME_VAR, MODEL_VERSION_VAR SELDON_MODEL_NAME_LABEL = "model_name" SELDON_MODEL_VERSION_LABEL = "model_version" @@ -28,8 +28,8 @@ def register(name: str, description: str) -> Histogram: def _get_labels_from_context() -> dict: try: - model_name = model_name_var.get() - model_version = model_version_var.get() + model_name = MODEL_NAME_VAR.get() + model_version = MODEL_VERSION_VAR.get() return { SELDON_MODEL_NAME_LABEL: model_name, SELDON_MODEL_VERSION_LABEL: model_version, diff --git a/tests/test_context.py b/tests/test_context.py index e7e8fa301..27fc071e0 100644 --- a/tests/test_context.py +++ b/tests/test_context.py @@ -3,7 +3,7 @@ from typing import Optional from mlserver.settings import ModelSettings, ModelParameters -from mlserver.context import model_context, model_name_var, model_version_var +from mlserver.context import model_context, MODEL_NAME_VAR, MODEL_VERSION_VAR from .fixtures import SumModel @@ -29,19 +29,19 @@ def test_model_context(name: str, version: Optional[str], expected_version: str) ) with pytest.raises(LookupError): - _ = model_name_var.get() + _ = MODEL_NAME_VAR.get() with pytest.raises(LookupError): - _ = model_version_var.get() + _ = MODEL_VERSION_VAR.get() with model_context(model_settings): - var_name = model_name_var.get() - var_version = model_version_var.get() + var_name = MODEL_NAME_VAR.get() + var_version = MODEL_VERSION_VAR.get() assert var_name == name assert var_version == expected_version with pytest.raises(LookupError): - _ = model_name_var.get() + _ = MODEL_NAME_VAR.get() with pytest.raises(LookupError): - _ = model_version_var.get() + _ = MODEL_VERSION_VAR.get() From 2a01680d966f44ede2d9d64f91c82145b707abc5 Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Fri, 21 Jul 2023 15:44:42 +0100 Subject: [PATCH 05/11] Test structured logging formatting --- tests/test_logging.py | 69 ++++++++++++++++++++++++++++--------------- 1 file changed, 46 insertions(+), 23 deletions(-) diff --git a/tests/test_logging.py b/tests/test_logging.py index 6b04ffb08..fcf7c7ed7 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -1,5 +1,3 @@ -import json - import pytest from mlserver import ModelSettings @@ -15,26 +13,37 @@ @pytest.mark.parametrize( - "name, version, expected_fmt", + "name, version, expected_model_fmt, fmt_present_in_all", [ ( "foo", "v1.0", "[foo:v1.0]", + False, ), ( "foo", "", "[foo]", + False, ), ( - "foo", - None, - "[foo]", + "", + "v1.0", + "", + True, + ), + ( + "", + "", + "", + True, ), ], ) -def test_model_logging_formatter_unstructured(name, version, expected_fmt, caplog): +def test_model_logging_formatter_unstructured( + name: str, version: str, expected_model_fmt: str, fmt_present_in_all: bool, caplog +): caplog.handler.setFormatter(ModelLoggerFormatter(use_structured_logging=False)) caplog.set_level(INFO) @@ -47,35 +56,46 @@ def test_model_logging_formatter_unstructured(name, version, expected_fmt, caplo logger.info("Inside model context") logger.info("After model context") - log_records = caplog.text.strip().split("\n") + log_records = caplog.get_records("call") assert len(log_records) == 3 - assert expected_fmt not in log_records[0] - assert expected_fmt in log_records[1] - assert expected_fmt not in log_records[2] + assert all(hasattr(lr, "model") for lr in log_records) + + if fmt_present_in_all: + assert all(lr.model == expected_model_fmt for lr in log_records) + else: + assert expected_model_fmt != log_records[0].model + assert expected_model_fmt == log_records[1].model + assert expected_model_fmt != log_records[2].model @pytest.mark.parametrize( - "name, version, expected_model_details", + "name, version, expected_model_fmt, fmt_present_in_all", [ ( "foo", "v1.0", - {"model_name", "model_version"} + ', "model_name": "foo", "model_version": "v1.0"', + False, ), ( "foo", "", - {"model_name"} + ', "model_name": "foo"', + False, ), ( - "foo", - None, - {"model_name"} + "", + "v1.0", + "", + True, ), + ("", "", "", True), ], ) -def test_model_logging_formatter_structured(name, version, expected_model_details, caplog): +def test_model_logging_formatter_structured( + name: str, version: str, expected_model_fmt: str, fmt_present_in_all: bool, caplog +): caplog.handler.setFormatter(ModelLoggerFormatter(use_structured_logging=True)) caplog.set_level(INFO) @@ -88,14 +108,17 @@ def test_model_logging_formatter_structured(name, version, expected_model_detail logger.info("Inside model context") logger.info("After model context") - log_records = caplog.text.strip().split("\n") + log_records = caplog.get_records("call") assert len(log_records) == 3 - json_log_records = [json.loads(lr) for lr in log_records] + assert all(hasattr(lr, "model") for lr in log_records) - assert not expected_model_details <= json_log_records[0].keys() - assert expected_model_details <= json_log_records[1].keys() - assert not expected_model_details <= json_log_records[2].keys() + if fmt_present_in_all: + assert all(lr.model == expected_model_fmt for lr in log_records) + else: + assert expected_model_fmt != log_records[0].model + assert expected_model_fmt == log_records[1].model + assert expected_model_fmt != log_records[2].model @pytest.mark.parametrize("debug", [True, False]) From 7ac12753a898445aa7f91158013364d144844255 Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Fri, 21 Jul 2023 15:58:04 +0100 Subject: [PATCH 06/11] Remove redundant dquote escaping in json logger format --- mlserver/logging.py | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/mlserver/logging.py b/mlserver/logging.py index 4e999ae12..92258e509 100644 --- a/mlserver/logging.py +++ b/mlserver/logging.py @@ -39,9 +39,10 @@ class ModelLoggerFormatter(logging.Formatter): """Log formatter incorporating model details, e.g. name and version.""" _UNSTRUCTURED_FORMAT = "%(asctime)s [%(name)s]%(model)s %(levelname)s - %(message)s" - _STRUCTURED_FORMAT = "{\"time\":\"%(asctime)s\", \"name\": \"%(name)s\", " \ - "\"level\": \"%(levelname)s\", \"message\": \"%(message)s\"" \ - " %(model)s}" + _STRUCTURED_FORMAT = ( + '{"time": "%(asctime)s", "name": "%(name)s", "level": "%(levelname)s", ' + '"message": "%(message)s" %(model)s}' + ) def __init__(self, use_structured_logging: bool): super().__init__( @@ -64,9 +65,9 @@ def _format_unstructured_model_details(name: str, version: str) -> str: def _format_structured_model_details(name: str, version: str) -> str: if not name: return "" - model_details = f", \"model_name\": \"{name}\"" + model_details = f', "model_name": "{name}"' if version: - model_details += f", \"model_version\": \"{version}\"" + model_details += f', "model_version": "{version}"' return model_details def format(self, record: logging.LogRecord) -> str: From 262ca74623da9ffab3c5196cc4a531c1ae4996e9 Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Fri, 21 Jul 2023 17:10:33 +0100 Subject: [PATCH 07/11] trigger GitHub actions --- docs/examples/mms/playing_with_mms.py | 0 1 file changed, 0 insertions(+), 0 deletions(-) create mode 100644 docs/examples/mms/playing_with_mms.py diff --git a/docs/examples/mms/playing_with_mms.py b/docs/examples/mms/playing_with_mms.py new file mode 100644 index 000000000..e69de29bb From f50f63efe9343e9a1ee5ed4f6f8a7bd65bbab32c Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Fri, 21 Jul 2023 17:21:40 +0100 Subject: [PATCH 08/11] Shorten flag description --- mlserver/settings.py | 2 +- tests/test_logging.py | 3 +++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/mlserver/settings.py b/mlserver/settings.py index 430a3033e..4d631c5a8 100644 --- a/mlserver/settings.py +++ b/mlserver/settings.py @@ -222,7 +222,7 @@ class Config: # Logging settings use_structured_logging: bool = False - """Use JSON-formatted structured logging instead of default human-readable format.""" + """Use JSON-formatted structured logging instead of default format.""" logging_settings: Optional[Union[str, Dict]] = None """Path to logging config file or dictionary configuration.""" diff --git a/tests/test_logging.py b/tests/test_logging.py index fcf7c7ed7..26d41980d 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -1,4 +1,6 @@ import pytest +import json + from mlserver import ModelSettings from mlserver.context import model_context @@ -108,6 +110,7 @@ def test_model_logging_formatter_structured( logger.info("Inside model context") logger.info("After model context") + _ = [json.loads(lr) for lr in caplog.text.strip().split("\n")] log_records = caplog.get_records("call") assert len(log_records) == 3 From 4b69b4473b79575f546ff1974f95fbbe3c64a526 Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Mon, 24 Jul 2023 14:16:25 +0100 Subject: [PATCH 09/11] Delete unused file --- docs/examples/mms/playing_with_mms.py | 0 1 file changed, 0 insertions(+), 0 deletions(-) delete mode 100644 docs/examples/mms/playing_with_mms.py diff --git a/docs/examples/mms/playing_with_mms.py b/docs/examples/mms/playing_with_mms.py deleted file mode 100644 index e69de29bb..000000000 From cf68aa1817f7698e643fe9603742fad54402c258 Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Tue, 25 Jul 2023 17:31:39 +0100 Subject: [PATCH 10/11] Override formatter on subsequent configurations when settings object is passed --- mlserver/logging.py | 35 +++++++++++++++++----------- tests/test_logging.py | 54 +++++++++++++++++++++++++++++++++++++++---- 2 files changed, 72 insertions(+), 17 deletions(-) diff --git a/mlserver/logging.py b/mlserver/logging.py index 92258e509..3c68d02ef 100644 --- a/mlserver/logging.py +++ b/mlserver/logging.py @@ -14,6 +14,8 @@ logger = logging.getLogger(LoggerName) +_STREAM_HANDLER_NAME = "stdout_stream_handler" + def get_logger(): return logger @@ -44,13 +46,15 @@ class ModelLoggerFormatter(logging.Formatter): '"message": "%(message)s" %(model)s}' ) - def __init__(self, use_structured_logging: bool): + def __init__(self, settings: Optional[Settings]): + self.use_structured_logging = ( + settings is not None and settings.use_structured_logging + ) super().__init__( self._STRUCTURED_FORMAT - if use_structured_logging + if self.use_structured_logging else self._UNSTRUCTURED_FORMAT ) - self.use_structured_logging = use_structured_logging @staticmethod def _format_unstructured_model_details(name: str, version: str) -> str: @@ -83,21 +87,26 @@ def format(self, record: logging.LogRecord) -> str: return super().format(record) +def _find_handler( + logger: logging.Logger, handler_name: str +) -> Optional[logging.Handler]: + for h in logger.handlers: + if h.get_name() == handler_name: + return h + return None + + def configure_logger(settings: Optional[Settings] = None): logger = get_logger() # Don't add handler twice - if not logger.handlers: - stream_handler = StreamHandler(sys.stdout) - - use_structured_logging = False - if settings and settings.use_structured_logging: - use_structured_logging = True - - formatter = ModelLoggerFormatter(use_structured_logging) - stream_handler.setFormatter(formatter) + handler = _find_handler(logger, _STREAM_HANDLER_NAME) + if handler is None: + handler = StreamHandler(sys.stdout) + handler.set_name(_STREAM_HANDLER_NAME) + logger.addHandler(handler) - logger.addHandler(stream_handler) + handler.setFormatter(ModelLoggerFormatter(settings)) logger.setLevel(logging.INFO) if settings and settings.debug: diff --git a/tests/test_logging.py b/tests/test_logging.py index 26d41980d..f39d97f4b 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -8,6 +8,7 @@ ModelLoggerFormatter, configure_logger, logger, + _STREAM_HANDLER_NAME, ) from mlserver.settings import ModelParameters, Settings from tests.fixtures import SumModel @@ -44,9 +45,15 @@ ], ) def test_model_logging_formatter_unstructured( - name: str, version: str, expected_model_fmt: str, fmt_present_in_all: bool, caplog + name: str, + version: str, + expected_model_fmt: str, + fmt_present_in_all: bool, + settings: Settings, + caplog, ): - caplog.handler.setFormatter(ModelLoggerFormatter(use_structured_logging=False)) + settings.use_structured_logging = False + caplog.handler.setFormatter(ModelLoggerFormatter(settings)) caplog.set_level(INFO) model_settings = ModelSettings( @@ -96,9 +103,15 @@ def test_model_logging_formatter_unstructured( ], ) def test_model_logging_formatter_structured( - name: str, version: str, expected_model_fmt: str, fmt_present_in_all: bool, caplog + name: str, + version: str, + expected_model_fmt: str, + fmt_present_in_all: bool, + settings: Settings, + caplog, ): - caplog.handler.setFormatter(ModelLoggerFormatter(use_structured_logging=True)) + settings.use_structured_logging = True + caplog.handler.setFormatter(ModelLoggerFormatter(settings)) caplog.set_level(INFO) model_settings = ModelSettings( @@ -136,3 +149,36 @@ def test_log_level_gets_persisted(debug: bool, settings: Settings, caplog): assert test_log_message in caplog.text else: assert test_log_message not in caplog.text + + +def test_configure_logger_when_called_multiple_times_with_same_logger(settings): + logger = configure_logger() + + assert len(logger.handlers) == 1 + handler = logger.handlers[0] + assert handler.name == _STREAM_HANDLER_NAME + assert ( + hasattr(handler.formatter, "use_structured_logging") + and handler.formatter.use_structured_logging is False + ) + + logger = configure_logger(settings) + + assert len(logger.handlers) == 1 + handler = logger.handlers[0] + assert handler.name == _STREAM_HANDLER_NAME + assert ( + hasattr(handler.formatter, "use_structured_logging") + and handler.formatter.use_structured_logging is False + ) + + settings.use_structured_logging = True + logger = configure_logger(settings) + + assert len(logger.handlers) == 1 + handler = logger.handlers[0] + assert handler.name == _STREAM_HANDLER_NAME + assert ( + hasattr(handler.formatter, "use_structured_logging") + and handler.formatter.use_structured_logging is True + ) From 3701066a176457e2a8598024335d9d0944bfea2c Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Wed, 26 Jul 2023 15:53:50 +0100 Subject: [PATCH 11/11] Lowercase global vars, they are not constants --- mlserver/context.py | 12 ++++++------ mlserver/logging.py | 6 +++--- mlserver/metrics/context.py | 6 +++--- tests/test_context.py | 14 +++++++------- 4 files changed, 19 insertions(+), 19 deletions(-) diff --git a/mlserver/context.py b/mlserver/context.py index 99c49471f..81d8fa1a9 100644 --- a/mlserver/context.py +++ b/mlserver/context.py @@ -3,21 +3,21 @@ from .settings import ModelSettings -MODEL_NAME_VAR: ContextVar[str] = ContextVar("model_name") -MODEL_VERSION_VAR: ContextVar[str] = ContextVar("model_version") +model_name_var: ContextVar[str] = ContextVar("model_name") +model_version_var: ContextVar[str] = ContextVar("model_version") @contextmanager def model_context(model_settings: ModelSettings): - model_name_token = MODEL_NAME_VAR.set(model_settings.name) + model_name_token = model_name_var.set(model_settings.name) model_version = "" if model_settings.version: model_version = model_settings.version - model_version_token = MODEL_VERSION_VAR.set(model_version) + model_version_token = model_version_var.set(model_version) try: yield finally: - MODEL_NAME_VAR.reset(model_name_token) - MODEL_VERSION_VAR.reset(model_version_token) + model_name_var.reset(model_name_token) + model_version_var.reset(model_version_token) diff --git a/mlserver/logging.py b/mlserver/logging.py index 3c68d02ef..ca2ad9183 100644 --- a/mlserver/logging.py +++ b/mlserver/logging.py @@ -7,7 +7,7 @@ from typing import Optional, Dict, Union import logging.config -from .context import MODEL_NAME_VAR, MODEL_VERSION_VAR +from .context import model_name_var, model_version_var from .settings import Settings LoggerName = "mlserver" @@ -75,8 +75,8 @@ def _format_structured_model_details(name: str, version: str) -> str: return model_details def format(self, record: logging.LogRecord) -> str: - model_name = MODEL_NAME_VAR.get("") - model_version = MODEL_VERSION_VAR.get("") + model_name = model_name_var.get("") + model_version = model_version_var.get("") record.model = ( self._format_structured_model_details(model_name, model_version) diff --git a/mlserver/metrics/context.py b/mlserver/metrics/context.py index 3b58f17fe..ccb828c11 100644 --- a/mlserver/metrics/context.py +++ b/mlserver/metrics/context.py @@ -2,7 +2,7 @@ from .registry import REGISTRY from .errors import InvalidModelContext -from ..context import MODEL_NAME_VAR, MODEL_VERSION_VAR +from ..context import model_name_var, model_version_var SELDON_MODEL_NAME_LABEL = "model_name" SELDON_MODEL_VERSION_LABEL = "model_version" @@ -28,8 +28,8 @@ def register(name: str, description: str) -> Histogram: def _get_labels_from_context() -> dict: try: - model_name = MODEL_NAME_VAR.get() - model_version = MODEL_VERSION_VAR.get() + model_name = model_name_var.get() + model_version = model_version_var.get() return { SELDON_MODEL_NAME_LABEL: model_name, SELDON_MODEL_VERSION_LABEL: model_version, diff --git a/tests/test_context.py b/tests/test_context.py index 27fc071e0..e7e8fa301 100644 --- a/tests/test_context.py +++ b/tests/test_context.py @@ -3,7 +3,7 @@ from typing import Optional from mlserver.settings import ModelSettings, ModelParameters -from mlserver.context import model_context, MODEL_NAME_VAR, MODEL_VERSION_VAR +from mlserver.context import model_context, model_name_var, model_version_var from .fixtures import SumModel @@ -29,19 +29,19 @@ def test_model_context(name: str, version: Optional[str], expected_version: str) ) with pytest.raises(LookupError): - _ = MODEL_NAME_VAR.get() + _ = model_name_var.get() with pytest.raises(LookupError): - _ = MODEL_VERSION_VAR.get() + _ = model_version_var.get() with model_context(model_settings): - var_name = MODEL_NAME_VAR.get() - var_version = MODEL_VERSION_VAR.get() + var_name = model_name_var.get() + var_version = model_version_var.get() assert var_name == name assert var_version == expected_version with pytest.raises(LookupError): - _ = MODEL_NAME_VAR.get() + _ = model_name_var.get() with pytest.raises(LookupError): - _ = MODEL_VERSION_VAR.get() + _ = model_version_var.get()