[Tests] Set logger in tests as human_extended (#5617)

Makefile

@@ -565,6 +565,7 @@ run-api: api ## Run mlrun api (dockerized)
 		--add-host host.docker.internal:host-gateway \
 		--env MLRUN_HTTPDB__DSN=$(MLRUN_HTTPDB__DSN) \
 		--env MLRUN_LOG_LEVEL=$(MLRUN_LOG_LEVEL) \
+		--env MLRUN_LOG_FORMATTER=$(MLRUN_LOG_FORMATTER) \
 		--env MLRUN_SECRET_STORES__TEST_MODE_MOCK_SECRETS=$(MLRUN_SECRET_STORES__TEST_MODE_MOCK_SECRETS) \
 		--env MLRUN_HTTPDB__REAL_PATH=$(MLRUN_HTTPDB__REAL_PATH) \
 		$(MLRUN_API_IMAGE_NAME_TAGGED)

mlrun/config.py

@@ -88,7 +88,7 @@
     "mpijob_crd_version": "",  # mpijob crd version (e.g: "v1alpha1". must be in: mlrun.runtime.MPIJobCRDVersions)
     "ipython_widget": True,
     "log_level": "INFO",
-    # log formatter (options: human | json)
+    # log formatter (options: human | human_extended | json)
     "log_formatter": "human",
     "submit_timeout": "180",  # timeout when submitting a new k8s resource
     # runtimes cleanup interval in seconds

mlrun/utils/logger.py

@@ -93,7 +93,25 @@ def _record_with(self, record):
 
 class HumanReadableExtendedFormatter(HumanReadableFormatter):
     def format(self, record) -> str:
-        more = self._resolve_more(record)
+        more = ""
+        record_with = self._record_with(record)
+        if record_with:
+
+            def _format_value(val):
+                formatted_val = (
+                    val
+                    if isinstance(val, str)
+                    else str(orjson.loads(self._json_dump(val)))
+                )
+                return (
+                    formatted_val.replace("\n", "\n\t\t")
+                    if len(formatted_val) < 4096
+                    else repr(formatted_val)
+                )
+
+            more = "\n\t" + "\n\t".join(
+                [f"{key}: {_format_value(val)}" for key, val in record_with.items()]
+            )
         return (
             "> "
             f"{self.formatTime(record, self.datefmt)} "
@@ -234,6 +252,15 @@ def resolve_formatter_by_kind(
     }[formatter_kind]
 
 
+def create_test_logger(name: str = "mlrun", stream: IO[str] = stdout) -> Logger:
+    return create_logger(
+        level="debug",
+        formatter_kind=FormatterKinds.HUMAN_EXTENDED.name,
+        name=name,
+        stream=stream,
+    )
+
+
 def create_logger(
     level: Optional[str] = None,
     formatter_kind: str = FormatterKinds.HUMAN.name,

tests/api/runtime_handlers/base.py

@@ -30,13 +30,13 @@
 import server.api.crud
 import server.api.utils.clients.chief
 from mlrun.common.runtimes.constants import PodPhases, RunStates
-from mlrun.utils import create_logger, now_date
+from mlrun.utils import create_test_logger, now_date
 from server.api.constants import LogSources
 from server.api.runtime_handlers import get_runtime_handler
 from server.api.utils.singletons.db import get_db
 from server.api.utils.singletons.k8s import get_k8s_helper
 
-logger = create_logger(level="debug", name="test-runtime-handlers")
+logger = create_test_logger(name="test-runtime-handlers")
 
 
 class TestRuntimeHandlerBase:

tests/api/runtimes/base.py

@@ -42,11 +42,11 @@
 from mlrun.common.runtimes.constants import PodPhases
 from mlrun.config import config as mlconf
 from mlrun.model import new_task
-from mlrun.utils import create_logger
+from mlrun.utils import create_test_logger
 from mlrun.utils.azure_vault import AzureVaultStore
 from server.api.utils.singletons.k8s import get_k8s_helper
 
-logger = create_logger(level="debug", name="test-runtime")
+logger = create_test_logger(name="test-runtime")
 
 
 class TestRuntimeBase(tests.api.conftest.MockedK8sHelper):

tests/conftest.py

@@ -55,6 +55,11 @@ def check_docker():
 
 # This must be *after* environment changes above
 from mlrun import RunObject, RunTemplate  # noqa
+from mlrun.utils import FormatterKinds, logger, resolve_formatter_by_kind  # noqa
+
+logger.get_handler("default").setFormatter(
+    resolve_formatter_by_kind(FormatterKinds.HUMAN_EXTENDED)()
+)
 
 
 def tag_test(spec: RunTemplate, name) -> RunTemplate:

tests/integration/sdk_api/base.py

@@ -24,9 +24,9 @@
 import mlrun.common.schemas
 import tests.conftest
 from mlrun.db.httpdb import HTTPRunDB
-from mlrun.utils import create_logger, retry_until_successful
+from mlrun.utils import FormatterKinds, create_test_logger, retry_until_successful
 
-logger = create_logger(level="debug", name="test-integration")
+logger = create_test_logger(name="test-integration")
 
 
 class TestMLRunIntegration:
@@ -142,6 +142,7 @@ def _run_api(self, extra_env=None):
                     "MLRUN_VERSION": "0.0.0+unstable",
                     "MLRUN_HTTPDB__DSN": self.db_dsn,
                     "MLRUN_LOG_LEVEL": "DEBUG",
+                    "MLRUN_LOG_FORMATTER": FormatterKinds.HUMAN_EXTENDED.value,
                     "MLRUN_SECRET_STORES__TEST_MODE_MOCK_SECRETS": "True",
                 },
                 extra_env,

tests/integration/sdk_api/run/test_main.py

@@ -255,7 +255,7 @@ def test_main_with_url_placeholder(self):
                     "--some-arg",
                 ],
                 True,
-                '"status":"completed"',
+                "status: completed",
             ],
         ],
     )

tests/system/base.py

@@ -24,9 +24,9 @@
 
 import mlrun.common.schemas
 from mlrun import get_run_db, mlconf
-from mlrun.utils import create_logger
+from mlrun.utils import create_test_logger
 
-logger = create_logger(level="debug", name="test-system")
+logger = create_test_logger(name="test-system")
 
 
 class TestMLRunSystem:

tests/utils/logger/test_logger.py

@@ -78,11 +78,11 @@ class SomePydanticObject(pydantic.BaseModel):
 
     # pydantic
     assert now_date_instance.isoformat() in log_line
-    assert '"name":"some-name"' in log_line
+    assert '"name":"some-name"' in log_line or "'name': 'some-name'" in log_line
 
     # dataclass
     assert another_now_date_instance.isoformat() in log_line
-    assert '"name":"another-name"' in log_line
+    assert '"name":"another-name"' in log_line or "'name': 'another-name'" in log_line
 
     # unbound class
     assert "UnboundClass" in log_line