From 76f8651607a0b67d35aebf669a311182daafa81a Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Mon, 17 Jul 2023 15:45:31 +0100 Subject: [PATCH 1/7] 602 Distinguish logs from different models by introducing a new log formatter --- docs/examples/model-repository/README.ipynb | 2 +- mlserver/context.py | 23 +++++++++ mlserver/handlers/dataplane.py | 5 +- mlserver/logging.py | 28 +++++++++-- mlserver/metrics/__init__.py | 3 +- mlserver/metrics/context.py | 23 +-------- mlserver/parallel/worker.py | 3 +- mlserver/registry.py | 43 +++++++++-------- tests/batching/conftest.py | 2 +- tests/logging/__init__.py | 0 tests/logging/conftest.py | 10 ++++ tests/logging/test_logging.py | 52 +++++++++++++++++++++ tests/metrics/test_context.py | 2 +- tests/test_context.py | 47 +++++++++++++++++++ 14 files changed, 191 insertions(+), 52 deletions(-) create mode 100644 mlserver/context.py create mode 100644 tests/logging/__init__.py create mode 100644 tests/logging/conftest.py create mode 100644 tests/logging/test_logging.py create mode 100644 tests/test_context.py diff --git a/docs/examples/model-repository/README.ipynb b/docs/examples/model-repository/README.ipynb index bd2cc1787..70625bda7 100644 --- a/docs/examples/model-repository/README.ipynb +++ b/docs/examples/model-repository/README.ipynb @@ -75,7 +75,7 @@ "cell_type": "markdown", "metadata": {}, "source": [ - "As we can, the repository lists 2 models (i.e. `mushroom-xgboost` and `mnist-svm`).\n", + "As we can see, the repository lists 2 models (i.e. `mushroom-xgboost` and `mnist-svm`).\n", "Note that the state for both is set to `READY`.\n", "This means that both models are loaded, and thus ready for inference." ] diff --git a/mlserver/context.py b/mlserver/context.py new file mode 100644 index 000000000..81d8fa1a9 --- /dev/null +++ b/mlserver/context.py @@ -0,0 +1,23 @@ +from contextlib import contextmanager +from contextvars import ContextVar + +from .settings import ModelSettings + +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_version = "" + if model_settings.version: + model_version = model_settings.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) diff --git a/mlserver/handlers/dataplane.py b/mlserver/handlers/dataplane.py index 15103862d..5e1f8ae39 100644 --- a/mlserver/handlers/dataplane.py +++ b/mlserver/handlers/dataplane.py @@ -5,7 +5,7 @@ from typing import Optional from ..errors import ModelNotReady -from ..metrics import model_context +from ..context import model_context from ..settings import Settings from ..registry import MultiModelRegistry from ..types import ( @@ -73,7 +73,8 @@ async def model_metadata( ) -> MetadataModelResponse: model = await self._model_registry.get_model(name, version) # TODO: Make await optional for sync methods - return await model.metadata() + with model_context(model.settings): + return await model.metadata() async def infer( self, diff --git a/mlserver/logging.py b/mlserver/logging.py index 3813a0ef2..4012b12de 100644 --- a/mlserver/logging.py +++ b/mlserver/logging.py @@ -2,15 +2,16 @@ import logging import sys -from logging import Formatter, StreamHandler +from logging import StreamHandler from pathlib import Path from typing import Optional, Dict, Union import logging.config +from .context import model_name_var, model_version_var from .settings import Settings LoggerName = "mlserver" -LoggerFormat = "%(asctime)s [%(name)s] %(levelname)s - %(message)s" +LoggerFormat = "%(asctime)s [%(name)s]%(model)s %(levelname)s - %(message)s" logger = logging.getLogger(LoggerName) @@ -35,13 +36,34 @@ def apply_logging_file(logging_settings: Union[str, Dict]): logger.warning("Unable to parse logging_settings.") +class ModelLoggerFormatter(logging.Formatter): + """ + A logging formatter that uses context variables to inject + the model name and version in the log message. + """ + @staticmethod + def _fmt_model(name: str, version: str) -> str: + if not name: + return "" + model_fmt = f"{name}:{version}" if version else name + return f"[{model_fmt}]" + + def format(self, record: logging.LogRecord) -> str: + model_name = model_name_var.get("") + model_version = model_version_var.get("") + + record.model = self.__class__._fmt_model(model_name, model_version) + + return super().format(record) + + def configure_logger(settings: Optional[Settings] = None): logger = get_logger() # Don't add handler twice if not logger.handlers: stream_handler = StreamHandler(sys.stdout) - formatter = Formatter(LoggerFormat) + formatter = ModelLoggerFormatter(LoggerFormat) stream_handler.setFormatter(formatter) logger.addHandler(stream_handler) diff --git a/mlserver/metrics/__init__.py b/mlserver/metrics/__init__.py index 3b572cce7..123729412 100644 --- a/mlserver/metrics/__init__.py +++ b/mlserver/metrics/__init__.py @@ -1,6 +1,7 @@ from .server import MetricsServer from .prometheus import configure_metrics -from .context import model_context, register, log +from .context import register, log +from ..context import model_context from .registry import REGISTRY __all__ = [ diff --git a/mlserver/metrics/context.py b/mlserver/metrics/context.py index 2c699b5df..ccb828c11 100644 --- a/mlserver/metrics/context.py +++ b/mlserver/metrics/context.py @@ -1,34 +1,13 @@ -from contextvars import ContextVar -from contextlib import contextmanager from prometheus_client import Histogram -from ..settings import ModelSettings from .registry import REGISTRY from .errors import InvalidModelContext - -model_name_var: ContextVar[str] = ContextVar("model_name") -model_version_var: ContextVar[str] = ContextVar("model_version") +from ..context import model_name_var, model_version_var SELDON_MODEL_NAME_LABEL = "model_name" SELDON_MODEL_VERSION_LABEL = "model_version" -@contextmanager -def model_context(model_settings: ModelSettings): - 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) - - try: - yield - finally: - model_name_var.reset(model_name_token) - model_version_var.reset(model_version_token) - - def register(name: str, description: str) -> Histogram: """ Registers a new metric with its description. diff --git a/mlserver/parallel/worker.py b/mlserver/parallel/worker.py index 5456e139d..e1a637341 100644 --- a/mlserver/parallel/worker.py +++ b/mlserver/parallel/worker.py @@ -12,7 +12,8 @@ from ..utils import install_uvloop_event_loop, schedule_with_callback from ..logging import configure_logger from ..settings import Settings -from ..metrics import configure_metrics, model_context +from ..metrics import configure_metrics +from ..context import model_context from ..env import Environment from .messages import ( diff --git a/mlserver/registry.py b/mlserver/registry.py index 9aa026f19..049c1f68c 100644 --- a/mlserver/registry.py +++ b/mlserver/registry.py @@ -4,6 +4,7 @@ from itertools import chain from functools import cmp_to_key +from .context import model_context from .model import MLModel from .errors import ModelNotFound from .logging import logger @@ -142,10 +143,11 @@ async def load(self, model_settings: ModelSettings) -> MLModel: new_model = self._model_initialiser(model_settings) - if previous_loaded_model: - await self._reload_model(previous_loaded_model, new_model) - else: - await self._load_model(new_model) + with model_context(model_settings): + if previous_loaded_model: + await self._reload_model(previous_loaded_model, new_model) + else: + await self._load_model(new_model) return new_model @@ -202,27 +204,28 @@ async def unload_version(self, version: Optional[str] = None): model = await self.get_model(version) await self._unload_model(model) - model_msg = f"model '{model.name}'" - if version: - model_msg = f"version {version} of {model_msg}" + async def _unload_model(self, model: MLModel): + with model_context(model.settings): + # NOTE: Every callback needs to run to ensure one doesn't block the + # others + await asyncio.gather( + *[callback(model) for callback in self._on_model_unload], + return_exceptions=True, + ) - logger.info(f"Unloaded {model_msg} succesfully.") + if model.version: + del self._versions[model.version] - async def _unload_model(self, model: MLModel): - # NOTE: Every callback needs to run to ensure one doesn't block the - # others - await asyncio.gather( - *[callback(model) for callback in self._on_model_unload], - return_exceptions=True, - ) + if model == self.default: + self._clear_default() - if model.version: - del self._versions[model.version] + model.ready = not await model.unload() - if model == self.default: - self._clear_default() + model_msg = f"model '{model.name}'" + if model.version: + model_msg = f"version {model.version} of {model_msg}" - model.ready = not await model.unload() + logger.info(f"Unloaded {model_msg} succesfully.") def _find_model(self, version: Optional[str] = None) -> Optional[MLModel]: if version: diff --git a/tests/batching/conftest.py b/tests/batching/conftest.py index b1b99075b..f951533d2 100644 --- a/tests/batching/conftest.py +++ b/tests/batching/conftest.py @@ -7,7 +7,7 @@ from mlserver.utils import generate_uuid from mlserver.types import InferenceRequest, TensorData from mlserver.model import MLModel -from mlserver.metrics.context import model_context +from mlserver.context import model_context from mlserver.batching.adaptive import AdaptiveBatcher from mlserver.settings import ModelSettings diff --git a/tests/logging/__init__.py b/tests/logging/__init__.py new file mode 100644 index 000000000..e69de29bb diff --git a/tests/logging/conftest.py b/tests/logging/conftest.py new file mode 100644 index 000000000..d820ed8b8 --- /dev/null +++ b/tests/logging/conftest.py @@ -0,0 +1,10 @@ +import logging +import pytest + +from mlserver.logging import ModelLoggerFormatter, LoggerFormat + + +# @pytest.fixture(autouse=True) +# def caplog_with_model_logger_formatter(caplog): +# caplog.handler.setFormatter(ModelLoggerFormatter(LoggerFormat)) +# caplog.set_level(logging.INFO) diff --git a/tests/logging/test_logging.py b/tests/logging/test_logging.py new file mode 100644 index 000000000..998d006f8 --- /dev/null +++ b/tests/logging/test_logging.py @@ -0,0 +1,52 @@ +import pytest + +from mlserver import ModelSettings +from mlserver.context import model_context +from mlserver.logging import ModelLoggerFormatter, LoggerFormat +from mlserver.settings import ModelParameters +from tests.fixtures import SumModel +from logging import getLogger, INFO + + +logger = getLogger("test.formatter") + + +@pytest.mark.parametrize( + "name, version, expected_fmt", + [ + ( + "foo", + "v1.0", + "[foo:v1.0]", + ), + ( + "foo", + "", + "[foo]", + ), + ( + "foo", + None, + "[foo]", + ), + ], +) +def test_model_logging_formatter(caplog, name, version, expected_fmt): + caplog.handler.setFormatter(ModelLoggerFormatter(LoggerFormat)) + 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(f"Inside model context") + logger.info("After model context") + + log_records = caplog.text.strip().split("\n") + assert len(caplog.messages) == 3 + + assert expected_fmt not in log_records[0] + assert expected_fmt in log_records[1] + assert expected_fmt not in log_records[2] diff --git a/tests/metrics/test_context.py b/tests/metrics/test_context.py index c5cc1b211..ffe96e98a 100644 --- a/tests/metrics/test_context.py +++ b/tests/metrics/test_context.py @@ -13,9 +13,9 @@ SELDON_MODEL_VERSION_LABEL, register, log, - model_context, _get_labels_from_context, ) +from mlserver.context import model_context from ..fixtures import SumModel diff --git a/tests/test_context.py b/tests/test_context.py new file mode 100644 index 000000000..e7e8fa301 --- /dev/null +++ b/tests/test_context.py @@ -0,0 +1,47 @@ +import pytest + +from typing import Optional + +from mlserver.settings import ModelSettings, ModelParameters +from mlserver.context import model_context, model_name_var, model_version_var +from .fixtures import SumModel + + +@pytest.mark.parametrize( + "name, version, expected_version", + [ + ( + "foo", + "v1.0", + "v1.0", + ), + ( + "foo", + "", + "", + ), + ("foo", None, ""), + ], +) +def test_model_context(name: str, version: Optional[str], expected_version: str): + model_settings = ModelSettings( + name=name, implementation=SumModel, parameters=ModelParameters(version=version) + ) + + with pytest.raises(LookupError): + _ = model_name_var.get() + + with pytest.raises(LookupError): + _ = model_version_var.get() + + with model_context(model_settings): + 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() + + with pytest.raises(LookupError): + _ = model_version_var.get() From 05d32282ae407a17bf0d0c83e9080e63f1d1c91a Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Mon, 17 Jul 2023 15:55:41 +0100 Subject: [PATCH 2/7] 602 Move logging test to package --- tests/logging/conftest.py | 10 ---------- tests/logging/test_logging.py | 25 ++++++++++++++++++------- tests/test_logging.py | 18 ------------------ 3 files changed, 18 insertions(+), 35 deletions(-) delete mode 100644 tests/logging/conftest.py delete mode 100644 tests/test_logging.py diff --git a/tests/logging/conftest.py b/tests/logging/conftest.py deleted file mode 100644 index d820ed8b8..000000000 --- a/tests/logging/conftest.py +++ /dev/null @@ -1,10 +0,0 @@ -import logging -import pytest - -from mlserver.logging import ModelLoggerFormatter, LoggerFormat - - -# @pytest.fixture(autouse=True) -# def caplog_with_model_logger_formatter(caplog): -# caplog.handler.setFormatter(ModelLoggerFormatter(LoggerFormat)) -# caplog.set_level(logging.INFO) diff --git a/tests/logging/test_logging.py b/tests/logging/test_logging.py index 998d006f8..fe1e5ccf0 100644 --- a/tests/logging/test_logging.py +++ b/tests/logging/test_logging.py @@ -2,13 +2,10 @@ from mlserver import ModelSettings from mlserver.context import model_context -from mlserver.logging import ModelLoggerFormatter, LoggerFormat -from mlserver.settings import ModelParameters +from mlserver.logging import ModelLoggerFormatter, LoggerFormat, configure_logger, logger +from mlserver.settings import ModelParameters, Settings from tests.fixtures import SumModel -from logging import getLogger, INFO - - -logger = getLogger("test.formatter") +from logging import INFO @pytest.mark.parametrize( @@ -31,7 +28,7 @@ ), ], ) -def test_model_logging_formatter(caplog, name, version, expected_fmt): +def test_model_logging_formatter(name, version, expected_fmt, caplog): caplog.handler.setFormatter(ModelLoggerFormatter(LoggerFormat)) caplog.set_level(INFO) @@ -50,3 +47,17 @@ def test_model_logging_formatter(caplog, name, version, expected_fmt): assert expected_fmt not in log_records[0] assert expected_fmt in log_records[1] assert expected_fmt not in log_records[2] + + +@pytest.mark.parametrize("debug", [True, False]) +def test_log_level_gets_persisted(debug: bool, settings: Settings, caplog): + settings.debug = debug + configure_logger(settings) + + test_log_message = "foo - bar - this is a test" + logger.debug(test_log_message) + + if debug: + assert test_log_message in caplog.text + else: + assert test_log_message not in caplog.text diff --git a/tests/test_logging.py b/tests/test_logging.py deleted file mode 100644 index 336e964fc..000000000 --- a/tests/test_logging.py +++ /dev/null @@ -1,18 +0,0 @@ -import pytest - -from mlserver.logging import logger, configure_logger -from mlserver.settings import Settings - - -@pytest.mark.parametrize("debug", [True, False]) -def test_log_level_gets_persisted(debug: bool, settings: Settings, caplog): - settings.debug = debug - configure_logger(settings) - - test_log_message = "foo - bar - this is a test" - logger.debug(test_log_message) - - if debug: - assert test_log_message in caplog.text - else: - assert test_log_message not in caplog.text From 3f642117dc500e6868064c7d838507e4f9b4a803 Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Mon, 17 Jul 2023 16:19:42 +0100 Subject: [PATCH 3/7] 602 Black --- mlserver/logging.py | 1 + tests/logging/test_logging.py | 7 ++++++- 2 files changed, 7 insertions(+), 1 deletion(-) diff --git a/mlserver/logging.py b/mlserver/logging.py index 4012b12de..1dc1da14d 100644 --- a/mlserver/logging.py +++ b/mlserver/logging.py @@ -41,6 +41,7 @@ class ModelLoggerFormatter(logging.Formatter): A logging formatter that uses context variables to inject the model name and version in the log message. """ + @staticmethod def _fmt_model(name: str, version: str) -> str: if not name: diff --git a/tests/logging/test_logging.py b/tests/logging/test_logging.py index fe1e5ccf0..6cb1e2adb 100644 --- a/tests/logging/test_logging.py +++ b/tests/logging/test_logging.py @@ -2,7 +2,12 @@ from mlserver import ModelSettings from mlserver.context import model_context -from mlserver.logging import ModelLoggerFormatter, LoggerFormat, configure_logger, logger +from mlserver.logging import ( + ModelLoggerFormatter, + LoggerFormat, + configure_logger, + logger, +) from mlserver.settings import ModelParameters, Settings from tests.fixtures import SumModel from logging import INFO From 8902b033f7d6b9a2f0482ad3d1172a8d71238e7f Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Mon, 17 Jul 2023 16:26:32 +0100 Subject: [PATCH 4/7] 602 Fixed lint problem --- tests/logging/test_logging.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/logging/test_logging.py b/tests/logging/test_logging.py index 6cb1e2adb..f315dd96e 100644 --- a/tests/logging/test_logging.py +++ b/tests/logging/test_logging.py @@ -43,7 +43,7 @@ def test_model_logging_formatter(name, version, expected_fmt, caplog): logger.info("Before model context") with model_context(model_settings): - logger.info(f"Inside model context") + logger.info("Inside model context") logger.info("After model context") log_records = caplog.text.strip().split("\n") From 61f3e9319b3cd34d69d6308ce3d5d109ebcfe49e Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Mon, 17 Jul 2023 16:28:30 +0100 Subject: [PATCH 5/7] 602 Fix import --- runtimes/alibi-detect/tests/conftest.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/runtimes/alibi-detect/tests/conftest.py b/runtimes/alibi-detect/tests/conftest.py index e3cdd9ef8..8604dd4a6 100644 --- a/runtimes/alibi-detect/tests/conftest.py +++ b/runtimes/alibi-detect/tests/conftest.py @@ -10,7 +10,7 @@ from alibi_detect.od import OutlierVAE from alibi_detect.saving import save_detector -from mlserver.metrics.context import model_context +from mlserver.context import model_context from mlserver.settings import ModelSettings, ModelParameters from mlserver.types import InferenceRequest from mlserver.utils import install_uvloop_event_loop From 4f27dcae2a7e98eaaf63b5025095f1086974eb3e Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Tue, 18 Jul 2023 13:15:27 +0100 Subject: [PATCH 6/7] 602 Flatten test logging folder and remove redundant import --- mlserver/metrics/__init__.py | 2 -- tests/logging/__init__.py | 0 tests/{logging => }/test_logging.py | 0 3 files changed, 2 deletions(-) delete mode 100644 tests/logging/__init__.py rename tests/{logging => }/test_logging.py (100%) diff --git a/mlserver/metrics/__init__.py b/mlserver/metrics/__init__.py index 123729412..4447f61fb 100644 --- a/mlserver/metrics/__init__.py +++ b/mlserver/metrics/__init__.py @@ -1,13 +1,11 @@ from .server import MetricsServer from .prometheus import configure_metrics from .context import register, log -from ..context import model_context from .registry import REGISTRY __all__ = [ "MetricsServer", "configure_metrics", - "model_context", "register", "log", "REGISTRY", diff --git a/tests/logging/__init__.py b/tests/logging/__init__.py deleted file mode 100644 index e69de29bb..000000000 diff --git a/tests/logging/test_logging.py b/tests/test_logging.py similarity index 100% rename from tests/logging/test_logging.py rename to tests/test_logging.py From c37065c949cd6518279899502d19fea14ab7ca42 Mon Sep 17 00:00:00 2001 From: Viktor Taskov Date: Tue, 18 Jul 2023 15:34:18 +0100 Subject: [PATCH 7/7] 602 Access method with self --- mlserver/logging.py | 2 +- mlserver/registry.py | 8 ++++---- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/mlserver/logging.py b/mlserver/logging.py index 1dc1da14d..c19158da6 100644 --- a/mlserver/logging.py +++ b/mlserver/logging.py @@ -53,7 +53,7 @@ def format(self, record: logging.LogRecord) -> str: model_name = model_name_var.get("") model_version = model_version_var.get("") - record.model = self.__class__._fmt_model(model_name, model_version) + record.model = self._fmt_model(model_name, model_version) return super().format(record) diff --git a/mlserver/registry.py b/mlserver/registry.py index 049c1f68c..262ac626c 100644 --- a/mlserver/registry.py +++ b/mlserver/registry.py @@ -166,7 +166,7 @@ async def _load_model(self, model: MLModel): self._register(model) model.ready = await model.load() - logger.info(f"Loaded model '{model.name}' succesfully.") + logger.info(f"Loaded model '{model.name}' successfully.") except Exception: logger.info( f"Couldn't load model '{model.name}'. " @@ -189,7 +189,7 @@ async def _reload_model(self, old_model: MLModel, new_model: MLModel): self._clear_default() old_model.ready = not await old_model.unload() - logger.info(f"Reloaded model '{new_model.name}' succesfully.") + logger.info(f"Reloaded model '{new_model.name}' successfully.") async def unload(self): models = await self.get_models() @@ -198,7 +198,7 @@ async def unload(self): self._versions.clear() self._clear_default() - logger.info(f"Unloaded all versions of model '{self._name}' succesfully.") + logger.info(f"Unloaded all versions of model '{self._name}' successfully.") async def unload_version(self, version: Optional[str] = None): model = await self.get_model(version) @@ -225,7 +225,7 @@ async def _unload_model(self, model: MLModel): if model.version: model_msg = f"version {model.version} of {model_msg}" - logger.info(f"Unloaded {model_msg} succesfully.") + logger.info(f"Unloaded {model_msg} successfully.") def _find_model(self, version: Optional[str] = None) -> Optional[MLModel]: if version: