Diagnostics plugin: tests and fixes

Author: Pedro Crespo

services/web/server/src/simcore_service_webserver/diagnostics_core.py

@@ -47,8 +47,9 @@ def observe(self, delay: float):
                 fifo.pop(0)
 
     def value(self) -> float:
-        return statistics.mean(self.last_delays)
-
+        if self.last_delays:
+            return statistics.mean(self.last_delays)
+        return 0
 
 def assert_healthy_app(app: web.Application) -> None:
     """ Diagnostics function that determins whether

services/web/server/src/simcore_service_webserver/diagnostics_entrypoints.py

@@ -17,7 +17,6 @@
 
 
 async def check_health(request: web.Request):
-
     # diagnostics of incidents
     try:
         assert_healthy_app(request.app)
@@ -50,13 +49,11 @@ async def get_diagnostics(request: web.Request):
     return web.json_response(data)
 
 
-def create_routes(specs: openapi.Spec) -> List[web.RouteDef]:
-    # TODO: consider the case in which server creates routes for both v0 and v1!!!
-    # TODO: should this be taken from servers instead?
-    # TODO: routing will be done automatically using operation_id/tags, etc...
-
+def create_rest_routes(specs: openapi.Spec) -> List[web.RouteDef]:
+    # NOTE: these are routes with paths starting with v0/* 
+   
     routes = []
-    base_path = openapi.get_base_path(specs)
+    base_path: str = openapi.get_base_path(specs)
 
     path, handle = "/", check_health
     operation_id = specs.paths[path].operations["get"].operation_id

services/web/server/src/simcore_service_webserver/diagnostics_monitoring.py

@@ -33,30 +33,49 @@ async def metrics_handler(request: web.Request):
 
 def middleware_factory(app_name: str) -> Coroutine:
     @web.middleware
-    async def middleware_handler(request: web.Request, handler):
+    async def _middleware_handler(request: web.Request, handler):
         try:
             request[kSTART_TIME] = time.time()
             request.app[kREQUEST_IN_PROGRESS].labels(
                 app_name, request.path, request.method
             ).inc()
 
             resp = await handler(request)
-            unhandled_exception = None
+            log_exception = None
+
+            assert isinstance(resp, web.Response), "Forgot envelope middleware?"  # nsec
+
+        except web.HTTPServerError as exc:
+            # Transforms exception into response object and log exception
+            resp = exc
+            log_exception = exc
 
         except web.HTTPException as exc:
-            # Transforms exception into response object
+            # Transforms non-HTTPServerError exceptions into response object
             resp = exc
-            unhandled_exception = None
+            log_exception = None
 
         except Exception as exc:  # pylint: disable=broad-except
             # Transforms unhandled exceptions into responses with status 500
             # NOTE: Prevents issue #1025
             resp = web.HTTPInternalServerError(reason=str(exc))
-            unhandled_exception = exc
+            log_exception = exc
 
         finally:
+            assert isinstance(  # nsec
+                resp, web.Response  # nsec
+            ), "Forgot envelope middleware or transformation?"  # nsec
+
             resp_time_secs: float = time.time() - request[kSTART_TIME]
 
+            exc_name = ""
+            if log_exception:
+                exc_name: str = log_exception.__class__.__name__
+
+            # Probes request latency
+            request.app[kLATENCY_PROBE].observe(resp_time_secs)
+
+            # prometheus probes
             request.app[kREQUEST_LATENCY].labels(app_name, request.path).observe(
                 resp_time_secs
             )
@@ -65,36 +84,29 @@ async def middleware_handler(request: web.Request, handler):
                 app_name, request.path, request.method
             ).dec()
 
-            exc_name: str = unhandled_exception.__class__.__name__ if unhandled_exception else ""
-
             request.app[kREQUEST_COUNT].labels(
                 app_name, request.method, request.path, resp.status, exc_name
             ).inc()
 
-            if unhandled_exception:
-                # NOTE: all access to API (i.e. and not other paths as /socket, /x, etc)
-                # shall return web.HTTPErrors since processed by error_middleware_factory
-                log.exception(
+            if log_exception:
+                log.error(
                     'Unexpected server error "%s" from access: %s "%s %s" done in %3.2f secs. Responding with status %s',
-                    type(unhandled_exception),
+                    type(log_exception),
                     request.remote,
                     request.method,
                     request.path,
                     resp_time_secs,
                     resp.status,
+                    exc_info=log_exception,
+                    stack_info=True,
                 )
 
-            # Probes for on-the-fly stats ---
-            # NOTE: might implement in the future some kind of statistical accumulator
-            # to perform incremental calculations on the fly
-
-            # Probes request latency
-            request.app[kLATENCY_PROBE].observe(resp_time_secs)
-
         return resp
 
-    middleware_handler.__middleware_name__ = f"{__name__}.{app_name}"
-    return middleware_handler
+    # adds identifier
+    _middleware_handler.__middleware_name__ = f"{__name__}.monitor_{app_name}"
+
+    return _middleware_handler
 
 
 def setup_monitoring(app: web.Application):
@@ -129,8 +141,20 @@ def setup_monitoring(app: web.Application):
     app[kLATENCY_PROBE] = DelayWindowProbe()
 
     # WARNING: ensure ERROR middleware is over this one
-    assert len(app.middlewares) >= 1  # nosec
-    app.middlewares.append(middleware_factory("simcore_service_webserver"))
+    #
+    # non-API request/response (e.g /metrics, /x/*  ...)
+    #                                 |
+    # API request/response (/v0/*)    |
+    #       |                         |
+    #       |                         |
+    #       v                         |
+    # ===== monitoring-middleware =====
+    # == rest-error-middlewarer ====  |
+    # ==           ...            ==  |
+    # == rest-envelope-middleware ==  v
+    #
+    #
+    app.middlewares.insert(0, middleware_factory("simcore_service_webserver"))
 
     # TODO: in production, it should only be accessible to backend services
     app.router.add_get("/metrics", metrics_handler)

services/web/server/src/simcore_service_webserver/diagnostics_plugin.py

@@ -6,20 +6,28 @@
 from aiohttp import web
 
 from servicelib import monitor_slow_callbacks
+from servicelib.application_setup import ModuleCategory, app_module_setup
 
 from .diagnostics_core import (
     IncidentsRegistry,
     kINCIDENTS_REGISTRY,
     kMAX_AVG_RESP_LATENCY,
     kMAX_TASK_DELAY,
 )
-from .diagnostics_entrypoints import create_routes
+from .diagnostics_entrypoints import create_rest_routes
 from .diagnostics_monitoring import setup_monitoring
 from .rest import APP_OPENAPI_SPECS_KEY
 
 log = logging.getLogger(__name__)
 
 
+@app_module_setup(
+    __name__,
+    ModuleCategory.ADDON,
+    depends=["simcore_service_webserver.rest"],
+    config_section="diagnostics",
+    logger=log,
+)
 def setup_diagnostics(
     app: web.Application,
     *,
@@ -64,9 +72,9 @@ def setup_diagnostics(
     app[kMAX_AVG_RESP_LATENCY] = max_avg_response_latency
     log.info("max_avg_response_latency = %3.2f secs ", max_avg_response_latency)
 
-    # 
-    # TODO: redesign ... to convoluted!!
-    registry = IncidentsRegistry(order_by=attrgetter("delay_secs")) 
+    #
+    # TODO: redesign ... too convoluted!!
+    registry = IncidentsRegistry(order_by=attrgetter("delay_secs"))
     app[kINCIDENTS_REGISTRY] = registry
 
     monitor_slow_callbacks.enable(max_task_delay, registry)
@@ -75,5 +83,5 @@ def setup_diagnostics(
     setup_monitoring(app)
 
     # adds other diagnostic routes: healthcheck, etc
-    routes = create_routes(specs=app[APP_OPENAPI_SPECS_KEY])
+    routes = create_rest_routes(specs=app[APP_OPENAPI_SPECS_KEY])
     app.router.add_routes(routes)