🚑️ tuning down scheduler for dynamic sidecars (ITISFoundation#3025)

* adding log level overwrite

* swapped out default log levels to warning for dysdcr

* strip duplicate network entries

* stripping extra errors

* fix log level error reporting

* making events trigger less frequently

* fixed failing test

* lowering log level

* literal

* replacing literal with validator

Co-authored-by: Andrei Neagu <[email protected]>

Author: GitHK

.env-devel

@@ -19,16 +19,14 @@ CATALOG_DEV_FEATURES_ENABLED=0
 DASK_SCHEDULER_HOST=dask-scheduler
 DASK_SCHEDULER_PORT=8786
 
-
-DYNAMIC_SIDECAR_IMAGE=${DOCKER_REGISTRY:-itisfoundation}/dynamic-sidecar:${DOCKER_IMAGE_TAG:-latest}
-
 DIRECTOR_REGISTRY_CACHING_TTL=900
 DIRECTOR_REGISTRY_CACHING=True
 
 COMPUTATIONAL_BACKEND_DEFAULT_CLUSTER_URL=tcp://dask-scheduler:8786
 DIRECTOR_V2_DEV_FEATURES_ENABLED=0
 
 DYNAMIC_SIDECAR_IMAGE=${DOCKER_REGISTRY:-itisfoundation}/dynamic-sidecar:${DOCKER_IMAGE_TAG:-latest}
+DYNAMIC_SIDECAR_LOG_LEVEL=DEBUG
 
 FUNCTION_SERVICES_AUTHORS='{"UN": {"name": "Unknown", "email": "[email protected]", "affiliation": "unknown"}}'
 

services/director-v2/src/simcore_service_director_v2/core/settings.py

@@ -148,6 +148,9 @@ class DynamicSidecarProxySettings(BaseCustomSettings):
 
 
 class DynamicSidecarSettings(BaseCustomSettings):
+    DYNAMIC_SIDECAR_LOG_LEVEL: str = Field(
+        "WARNING", description="log level of the dynamic sidecar"
+    )
     SC_BOOT_MODE: BootModeEnum = Field(
         BootModeEnum.PRODUCTION,
         description="Used to compute where or not should start sidecar in development mode",
@@ -274,6 +277,14 @@ class DynamicSidecarSettings(BaseCustomSettings):
     def strip_leading_slashes(cls, v) -> str:
         return v.lstrip("/")
 
+    @validator("DYNAMIC_SIDECAR_LOG_LEVEL")
+    @classmethod
+    def validate_log_level(cls, v) -> str:
+        valid_log_levels = {"DEBUG", "INFO", "WARNING", "ERROR"}
+        if v not in valid_log_levels:
+            raise ValueError(f"Log level must be one of {valid_log_levels} not {v}")
+        return v
+
 
 class DynamicServicesSchedulerSettings(BaseCustomSettings):
     DIRECTOR_V2_DYNAMIC_SCHEDULER_ENABLED: bool = True

services/director-v2/src/simcore_service_director_v2/models/schemas/dynamic_services/scheduler.py

@@ -61,7 +61,6 @@ def update_ok_status(self, info: str) -> None:
         self._update(DynamicSidecarStatus.OK, info)
 
     def update_failing_status(self, info: str) -> None:
-        logger.error(info)
         self._update(DynamicSidecarStatus.FAILING, info)
 
     def __eq__(self, other: "Status") -> bool:

services/director-v2/src/simcore_service_director_v2/modules/dynamic_sidecar/docker_compose_specs.py

@@ -36,7 +36,10 @@ def _inject_proxy_network_configuration(
     target_container_spec = service_spec["services"][target_container]
     container_networks = target_container_spec.get("networks", [])
     container_networks.append(dynamic_sidecar_network_name)
-    target_container_spec["networks"] = container_networks
+    # avoid duplicate entries, this is important when the dynamic-sidecar
+    # fails to run docker-compose up, otherwise it will
+    # continue adding lots of entries to this list
+    target_container_spec["networks"] = list(set(container_networks))
 
 
 class _environment_section:

services/director-v2/src/simcore_service_director_v2/modules/dynamic_sidecar/docker_service_specs/sidecar.py

@@ -34,6 +34,7 @@ def _get_environment_variables(
         state_exclude = scheduler_data.paths_mapping.state_exclude
 
     return {
+        "LOG_LEVEL": app_settings.DYNAMIC_SERVICES.DYNAMIC_SIDECAR.DYNAMIC_SIDECAR_LOG_LEVEL,
         "SIMCORE_HOST_NAME": scheduler_data.service_name,
         "DYNAMIC_SIDECAR_COMPOSE_NAMESPACE": compose_namespace,
         "DY_SIDECAR_PATH_INPUTS": f"{scheduler_data.paths_mapping.inputs_path}",

services/director-v2/src/simcore_service_director_v2/modules/dynamic_sidecar/scheduler/task.py

@@ -70,6 +70,8 @@ async def _apply_observation_cycle(
             dynamic_sidecar_settings=dynamic_services_settings.DYNAMIC_SIDECAR,
         )
     ):
+        # NOTE: once marked for removal the observation cycle needs
+        # to continue in order for the service to be removed
         logger.warning(
             "Removing service %s from observation", scheduler_data.service_name
         )
@@ -168,7 +170,6 @@ async def mark_service_for_removal(
             )
             await update_scheduler_data_label(current.scheduler_data)
 
-        self._enqueue_observation_from_service_name(service_name)
         logger.debug("Service '%s' marked for removal from scheduler", service_name)
 
     async def finish_service_removal(self, node_uuid: NodeID) -> None:
@@ -399,7 +400,7 @@ async def observing_single_service(service_name: str) -> None:
                 # fire and forget about the task
                 asyncio.create_task(
                     observing_single_service(service_name),
-                    name=f"observe {service_name}",
+                    name=f"observe_{service_name}",
                 )
 
         logger.info("Scheduler 'trigger observation queue task' was shut down")
@@ -417,13 +418,15 @@ async def _run_scheduler_task(self) -> None:
                 async with self._lock:
                     for service_name in self._to_observe:
                         self._enqueue_observation_from_service_name(service_name)
-
-                await sleep(settings.DIRECTOR_V2_DYNAMIC_SCHEDULER_INTERVAL_SECONDS)
             except asyncio.CancelledError:  # pragma: no cover
                 logger.info("Stopped dynamic scheduler")
                 raise
             except Exception:  # pylint: disable=broad-except
-                logger.error("Unexpected error in dynamic scheduler", exc_info=True)
+                logger.exception(
+                    "Unexpected error while scheduling sidecars observation"
+                )
+
+            await sleep(settings.DIRECTOR_V2_DYNAMIC_SCHEDULER_INTERVAL_SECONDS)
 
     async def _discover_running_services(self) -> None:
         """discover all services which were started before and add them to the scheduler"""

services/director-v2/tests/integration/02/test_dynamic_sidecar_nodeports_integration.py

@@ -319,6 +319,7 @@ def mock_env(
 
     monkeypatch.setenv("SC_BOOT_MODE", "production")
     monkeypatch.setenv("DYNAMIC_SIDECAR_EXPOSE_PORT", "true")
+    monkeypatch.setenv("DYNAMIC_SIDECAR_LOG_LEVEL", "DEBUG")
     monkeypatch.setenv("PROXY_EXPOSE_PORT", "true")
     monkeypatch.setenv("SIMCORE_SERVICES_NETWORK_NAME", network_name)
     monkeypatch.delenv("DYNAMIC_SIDECAR_MOUNT_PATH_DEV", raising=False)

services/director-v2/tests/unit/test_modules_dynamic_sidecar_docker_service_specs_sidecar.py

@@ -31,6 +31,7 @@
 }
 
 EXPECTED_DYNAMIC_SIDECAR_ENV_VAR_NAMES = {
+    "LOG_LEVEL",
     "DY_SIDECAR_NODE_ID",
     "DY_SIDECAR_PATH_INPUTS",
     "DY_SIDECAR_PATH_OUTPUTS",

services/dynamic-sidecar/src/simcore_service_dynamic_sidecar/core/settings.py

@@ -22,7 +22,7 @@ class DynamicSidecarSettings(BaseCustomSettings):
     )
 
     # LOGGING
-    LOG_LEVEL: str = Field("DEBUG")
+    LOG_LEVEL: str = Field("WARNING")
 
     @validator("LOG_LEVEL")
     @classmethod