♻️Sidecars: Image pulling is now a debug log, try to guess log level …

…of services (#4232)

packages/dask-task-models-library/src/dask_task_models_library/container_tasks/events.py

@@ -1,6 +1,6 @@
 import logging
 from abc import ABC, abstractmethod
-from typing import Union
+from typing import TypeAlias, Union
 
 from distributed.worker import get_worker
 from pydantic import BaseModel, Extra, NonNegativeFloat
@@ -45,17 +45,21 @@ class Config(BaseTaskEvent.Config):
         }
 
 
+LogMessageStr: TypeAlias = str
+LogLevelInt: TypeAlias = int
+
+
 class TaskLogEvent(BaseTaskEvent):
-    log: str
-    log_level: int = logging.INFO
+    log: LogMessageStr
+    log_level: LogLevelInt
 
     @staticmethod
     def topic_name() -> str:
         return "task_logs"
 
     @classmethod
-    def from_dask_worker(cls, log: str) -> "TaskLogEvent":
-        return cls(job_id=get_worker().get_current_task(), log=log)
+    def from_dask_worker(cls, log: str, log_level: LogLevelInt) -> "TaskLogEvent":
+        return cls(job_id=get_worker().get_current_task(), log=log, log_level=log_level)
 
     class Config(BaseTaskEvent.Config):
         schema_extra = {

packages/dask-task-models-library/tests/container_tasks/test_events.py

@@ -5,6 +5,8 @@
 # pylint:disable=protected-access
 # pylint:disable=too-many-arguments
 
+import logging
+
 import pytest
 from dask_task_models_library.container_tasks.events import (
     BaseTaskEvent,
@@ -51,7 +53,10 @@ def test_task_progress_from_worker(mocked_dask_worker_job_id: str):
 
 
 def test_task_log_from_worker(mocked_dask_worker_job_id: str):
-    event = TaskLogEvent.from_dask_worker(log="here is the amazing logs")
+    event = TaskLogEvent.from_dask_worker(
+        log="here is the amazing logs", log_level=logging.INFO
+    )
 
     assert event.job_id == mocked_dask_worker_job_id
     assert event.log == "here is the amazing logs"
+    assert event.log_level == logging.INFO

packages/models-library/src/models_library/rabbitmq_messages.py

@@ -1,7 +1,7 @@
 import logging
 from abc import abstractmethod
 from enum import Enum, auto
-from typing import Any, Literal
+from typing import Any, Literal, TypeAlias
 
 from models_library.projects import ProjectID
 from models_library.projects_nodes_io import NodeID
@@ -11,6 +11,9 @@
 from pydantic import BaseModel, Field
 from pydantic.types import NonNegativeFloat
 
+LogLevelInt: TypeAlias = int
+LogMessageStr: TypeAlias = str
+
 
 class RabbitEventMessageType(str, Enum):
     RELOAD_IFRAME = "RELOAD_IFRAME"
@@ -47,8 +50,8 @@ class NodeMessageBase(ProjectMessageBase):
 
 class LoggerRabbitMessage(RabbitMessageBase, NodeMessageBase):
     channel_name: Literal["simcore.services.logs.v2"] = "simcore.services.logs.v2"
-    messages: list[str]
-    log_level: int = logging.INFO
+    messages: list[LogMessageStr]
+    log_level: LogLevelInt = logging.INFO
 
     def routing_key(self) -> str:
         return f"{self.project_id}.{self.log_level}"

packages/service-library/src/servicelib/logging_utils.py

@@ -12,7 +12,7 @@
 from asyncio import iscoroutinefunction
 from contextlib import contextmanager
 from inspect import getframeinfo, stack
-from typing import Callable, TypedDict
+from typing import Callable, TypeAlias, TypedDict
 
 log = logging.getLogger(__name__)
 
@@ -247,3 +247,20 @@ def get_log_record_extra(*, user_id: int | str | None = None) -> LogExtra | None
         assert int(user_id) > 0  # nosec
         extra["log_uid"] = f"{user_id}"
     return extra or None
+
+
+LogLevelInt: TypeAlias = int
+LogMessageStr: TypeAlias = str
+
+
+def guess_message_log_level(message: str) -> LogLevelInt:
+    lower_case_message = message.lower().strip()
+    if lower_case_message.startswith(
+        ("error:", "err:", "error ", "err ", "[error]", "[err]")
+    ):
+        return logging.ERROR
+    if lower_case_message.startswith(
+        ("warning:", "warn:", "warning ", "warn ", "[warning]", "[warn]")
+    ):
+        return logging.WARNING
+    return logging.INFO

packages/service-library/tests/test_logging_utils.py

@@ -2,11 +2,15 @@
 
 import logging
 from threading import Thread
-from typing import Optional
 
 import pytest
 from pytest import LogCaptureFixture
-from servicelib.logging_utils import log_decorator
+from servicelib.logging_utils import (
+    LogLevelInt,
+    LogMessageStr,
+    guess_message_log_level,
+    log_decorator,
+)
 from servicelib.utils import logged_gather
 
 logger = logging.getLogger(__name__)
@@ -15,7 +19,7 @@
 @pytest.mark.parametrize("logger", [None, logger])
 @pytest.mark.parametrize("log_traceback", [True, False])
 async def test_error_regression_async_def(
-    caplog: LogCaptureFixture, logger: Optional[logging.Logger], log_traceback: bool
+    caplog: LogCaptureFixture, logger: logging.Logger | None, log_traceback: bool
 ):
     @log_decorator(logger, log_traceback=log_traceback)
     async def _raising_error() -> None:
@@ -34,7 +38,7 @@ async def _raising_error() -> None:
 @pytest.mark.parametrize("logger", [None, logger])
 @pytest.mark.parametrize("log_traceback", [True, False])
 async def test_error_regression_def(
-    caplog: LogCaptureFixture, logger: Optional[logging.Logger], log_traceback: bool
+    caplog: LogCaptureFixture, logger: logging.Logger | None, log_traceback: bool
 ):
     @log_decorator(logger, log_traceback=log_traceback)
     def _raising_error() -> None:
@@ -50,3 +54,28 @@ def _raising_error() -> None:
         assert "Traceback" in caplog.text
     else:
         assert "Traceback" not in caplog.text
+
+
+@pytest.mark.parametrize(
+    "message, expected_log_level",
+    [
+        ("", logging.INFO),
+        ("Error: this is an error", logging.ERROR),
+        ("[Error] this is an error", logging.ERROR),
+        ("[Error]: this is an error", logging.ERROR),
+        ("[Err] this is an error", logging.ERROR),
+        ("[Err]: this is an error", logging.ERROR),
+        ("Err: this is an error", logging.ERROR),
+        ("Warning: this is an warning", logging.WARNING),
+        ("[Warning] this is an warning", logging.WARNING),
+        ("[Warning]: this is an warning", logging.WARNING),
+        ("[Warn] this is an warning", logging.WARNING),
+        ("[Warn]: this is an warning", logging.WARNING),
+        ("Warn: this is an warning", logging.WARNING),
+        ("Not a Warn: this is an warning", logging.INFO),
+    ],
+)
+def test_guess_message_log_level(
+    message: LogMessageStr, expected_log_level: LogLevelInt
+):
+    assert guess_message_log_level(message) == expected_log_level

packages/settings-library/src/settings_library/docker_registry.py

@@ -1,19 +1,18 @@
 from functools import cached_property
-from typing import Optional
 
 from pydantic import Field, SecretStr, validator
 
 from .base import BaseCustomSettings
 
 
 class RegistrySettings(BaseCustomSettings):
-
     REGISTRY_AUTH: bool = Field(..., description="do registry authentication")
-    REGISTRY_PATH: Optional[str] = Field(
-        None, description="development mode only, in case a local registry is used"
+    REGISTRY_PATH: str | None = Field(
+        default=None,
+        description="development mode only, in case a local registry is used",
     )
     # NOTE: name is missleading, http or https protocol are not included
-    REGISTRY_URL: str = Field("", description="address to the docker registry")
+    REGISTRY_URL: str = Field(default="", description="address to the docker registry")
 
     REGISTRY_USER: str = Field(
         ..., description="username to access the docker registry"
@@ -25,7 +24,7 @@ class RegistrySettings(BaseCustomSettings):
 
     @validator("REGISTRY_PATH", pre=True)
     @classmethod
-    def escape_none_string(cls, v) -> Optional[str]:
+    def escape_none_string(cls, v) -> str | None:
         return None if v == "None" else v
 
     @cached_property

services/dask-sidecar/src/simcore_service_dask_sidecar/computational_sidecar/constants.py

@@ -0,0 +1,19 @@
+import re
+from typing import Final
+
+LEGACY_SERVICE_LOG_FILE_NAME: Final[str] = "log.dat"
+PARSE_LOG_INTERVAL_S: Final[float] = 0.5
+
+DOCKER_LOG_REGEXP: re.Pattern[str] = re.compile(
+    r"^(?P<timestamp>(?:(\d{4}-\d{2}-\d{2})T(\d{2}:\d{2}:\d{2}(?:\.\d+)?))(Z|[\+-]\d{2}:\d{2})?)"
+    r"\s(?P<log>.*)$"
+)
+PROGRESS_REGEXP: re.Pattern[str] = re.compile(
+    r"^(?:\[?progress\]?:?)?\s*"
+    r"(?P<value>[0-1]?\.\d+|"
+    r"\d+\s*(?:(?P<percent_sign>%)|"
+    r"\d+\s*"
+    r"(?P<percent_explicit>percent))|"
+    r"\[?(?P<fraction>\d+\/\d+)\]?"
+    r"|0|1)"
+)

services/dask-sidecar/src/simcore_service_dask_sidecar/computational_sidecar/core.py

@@ -1,5 +1,6 @@
 import asyncio
 import json
+import logging
 import os
 import socket
 from dataclasses import dataclass
@@ -23,6 +24,7 @@
 from packaging import version
 from pydantic import ValidationError
 from pydantic.networks import AnyUrl
+from servicelib.logging_utils import LogLevelInt, LogMessageStr
 from settings_library.s3 import S3Settings
 from yarl import URL
 
@@ -155,12 +157,14 @@ async def _retrieve_output_data(
                 exc=exc,
             ) from exc
 
-    async def _publish_sidecar_log(self, log: str) -> None:
+    async def _publish_sidecar_log(
+        self, log: LogMessageStr, log_level: LogLevelInt = logging.INFO
+    ) -> None:
         publish_event(
             self.task_publishers.logs,
-            TaskLogEvent.from_dask_worker(log=f"[sidecar] {log}"),
+            TaskLogEvent.from_dask_worker(log=f"[sidecar] {log}", log_level=log_level),
         )
-        logger.info(log)
+        logger.log(log_level, log)
 
     async def run(self, command: list[str]) -> TaskOutputData:
         await self._publish_sidecar_log(
@@ -253,7 +257,9 @@ async def __aexit__(
         tb: TracebackType | None,
     ) -> None:
         if exc:
-            await self._publish_sidecar_log(f"Task error:\n{exc}")
             await self._publish_sidecar_log(
-                "There might be more information in the service log file"
+                f"Task error:\n{exc}", log_level=logging.ERROR
+            )
+            await self._publish_sidecar_log(
+                "TIP: There might be more information in the service log file in the service outputs",
             )