🐛 fixes unhandled exception when parsing an invalid string (ITISFoundation#2608)

An unhandled exception is causing the director service to respond with 500 every time is requested to list running services services.

The exception displayed ValueError: unconverted data remains: Z and was raised while parsing an invalid string into a datetime. utils. parse_as_datetime solved that.

Author: pcrespov

services/director/src/simcore_service_director/producer.py

@@ -13,14 +13,13 @@
 import aiodocker
 import tenacity
 from aiohttp import ClientConnectionError, ClientSession, web
-
-from servicelib.async_utils import (
+from servicelib.async_utils import (  # pylint: disable=no-name-in-module
     run_sequentially_in_context,
-)  # pylint: disable=no-name-in-module
-from servicelib.monitor_services import (
+)
+from servicelib.monitor_services import (  # pylint: disable=no-name-in-module
     service_started,
     service_stopped,
-)  # pylint: disable=no-name-in-module
+)
 
 from . import config, docker_utils, exceptions, registry_proxy
 from .config import (
@@ -30,6 +29,7 @@
 )
 from .services_common import ServicesCommonSettings
 from .system_utils import get_system_extra_hosts_raw
+from .utils import parse_as_datetime
 
 log = logging.getLogger(__name__)
 
@@ -503,9 +503,6 @@ async def _remove_overlay_network_of_swarm(
         ) from err
 
 
-DATETIME_FORMAT = "%Y-%m-%dT%H:%M:%S.%fZ"
-
-
 async def _get_service_state(
     client: aiodocker.docker.Docker, service: Dict
 ) -> Tuple[ServiceState, str]:
@@ -532,18 +529,7 @@ async def _wait_for_tasks(tasks):
     last_task = sorted(tasks, key=lambda task: task["UpdatedAt"])[-1]
     task_state = last_task["Status"]["State"]
 
-    def _to_datetime(datetime_str: str) -> datetime:
-        # datetime_str is typically '2020-10-09T12:28:14.771034099Z'
-        #  - The T separates the date portion from the time-of-day portion
-        #  - The Z on the end means UTC, that is, an offset-from-UTC
-        # The 099 before the Z is not clear, therefore we will truncate the last part
-        N = len("2020-10-09T12:28:14.7710")
-        if len(datetime_str) > N:
-            datetime_str = datetime_str[:N]
-        return datetime.strptime(datetime_str, "%Y-%m-%dT%H:%M:%S.%f")
-
-    task_state_update_time = _to_datetime(last_task["Status"]["Timestamp"])
-    log.debug("%s %s: time %s", service["ID"], task_state, task_state_update_time)
+    log.debug("%s %s", service["ID"], task_state)
 
     last_task_state = ServiceState.STARTING  # default
     last_task_error_msg = (
@@ -573,14 +559,20 @@ def _to_datetime(datetime_str: str) -> datetime:
         last_task_state = ServiceState.STARTING
     elif task_state in ("running"):
         now = datetime.utcnow()
+        # NOTE: task_state_update_time is only used to discrimitate between 'starting' and 'running'
+        task_state_update_time = parse_as_datetime(
+            last_task["Status"]["Timestamp"], default=now
+        )
         time_since_running = now - task_state_update_time
+
         log.debug("Now is %s, time since running mode is %s", now, time_since_running)
         if time_since_running > timedelta(
             seconds=config.DIRECTOR_SERVICES_STATE_MONITOR_S
         ):
             last_task_state = ServiceState.RUNNING
         else:
             last_task_state = ServiceState.STARTING
+
     elif task_state in ("complete", "shutdown"):
         last_task_state = ServiceState.COMPLETE
     log.debug("service running state is %s", last_task_state)

services/director/src/simcore_service_director/utils.py

@@ -0,0 +1,28 @@
+import logging
+from datetime import datetime
+from typing import Optional
+
+log = logging.getLogger(__name__)
+
+DATETIME_FORMAT = "%Y-%m-%dT%H:%M:%S.%f"
+_MAXLEN = len("2020-10-09T12:28:14.7710")
+
+
+def parse_as_datetime(timestr: str, *, default: Optional[datetime] = None) -> datetime:
+    """
+    default: if parsing is not possible, it returs default
+    """
+    # datetime_str is typically '2020-10-09T12:28:14.771034099Z'
+    #  - The T separates the date portion from the time-of-day portion
+    #  - The Z on the end means UTC, that is, an offset-from-UTC
+    # The 099 before the Z is not clear, therefore we will truncate the last part
+
+    try:
+        timestr = timestr.strip("Z ")[:_MAXLEN]
+        dt = datetime.strptime(timestr, DATETIME_FORMAT)
+        return dt
+    except ValueError as err:
+        log.debug("Failed to parse %s: %s", timestr, err)
+        if default is not None:
+            return default
+        raise

services/director/tests/test_utils.py

@@ -0,0 +1,38 @@
+from datetime import datetime
+
+import pytest
+from simcore_service_director.utils import parse_as_datetime
+
+
+@pytest.mark.parametrize(
+    "timestr",
+    (
+        # Samples taken from https://docs.docker.com/engine/reference/commandline/service_inspect/
+        "2020-10-09T18:44:02.558012087Z",
+        "2020-10-09T12:28:14.771034099Z",
+        "2020-10-09T12:28:14.7710",
+        # found cases with spaces
+        "2020-10-09T12:28:14.77 Z",
+        "  2020-10-09T12:28:14.77  ",
+    ),
+)
+def test_parse_valid_time_strings(timestr):
+
+    dt = parse_as_datetime(timestr)
+    assert isinstance(dt, datetime)
+    assert dt.year == 2020
+    assert dt.month == 10
+    assert dt.day == 9
+
+
+def test_parse_invalid_timestr():
+    now = datetime.utcnow()
+    invalid_timestr = "2020-10-09T12:28"
+
+    # w/ default, it should NOT raise
+    dt = parse_as_datetime(invalid_timestr, default=now)
+    assert dt == now
+
+    # w/o default
+    with pytest.raises(ValueError):
+        parse_as_datetime(invalid_timestr)