[mock_uss] Improve mock_uss behavior visibility (#792)

monitoring/mock_uss/__init__.py

@@ -76,6 +76,7 @@ def require_config_value(config_key: str) -> None:
 
 from monitoring.mock_uss import config
 from monitoring.mock_uss import routes as basic_routes
+from monitoring.mock_uss import logging
 
 if SERVICE_GEOAWARENESS in webapp.config[config.KEY_SERVICES]:
     enabled_services.add(SERVICE_GEOAWARENESS)

monitoring/mock_uss/gunicorn.conf.py

@@ -21,27 +21,36 @@ def when_ready(server: Arbiter):
     webapp.start_periodic_tasks_daemon()
 
 
+def _skip_logging(req: Request) -> bool:
+    # Status endpoint is polled constantly for liveness; to avoid filling logs, we don't log it
+    if req.path == "/status" and req.method == "GET":
+        return True
+    return False
+
+
 def pre_request(worker: Worker, req: Request):
     """gunicorn server hook called just before a worker processes the request."""
-    logger.debug(
-        "gunicorn pre_request from worker {} (OS PID {}): {} {}",
-        worker.pid,
-        os.getpid(),
-        req.method,
-        req.path,
-    )
+    if not _skip_logging(req):
+        logger.debug(
+            "gunicorn pre_request from worker {} (OS PID {}): {} {}",
+            worker.pid,
+            os.getpid(),
+            req.method,
+            req.path,
+        )
 
 
 def post_request(worker: Worker, req: Request, environ: dict, resp: Response):
     """gunicorn server hook called after a worker processes the request."""
-    logger.debug(
-        "gunicorn post_request from worker {} (OS PID {}): {} {} -> {}",
-        worker.pid,
-        os.getpid(),
-        req.method,
-        req.path,
-        resp.status_code,
-    )
+    if not _skip_logging(req):
+        logger.debug(
+            "gunicorn post_request from worker {} (OS PID {}): {} {} -> {}",
+            worker.pid,
+            os.getpid(),
+            req.method,
+            req.path,
+            resp.status_code,
+        )
 
 
 def worker_abort(worker: Worker):

monitoring/mock_uss/logging.py

@@ -0,0 +1,92 @@
+from __future__ import annotations
+
+import json
+import os
+from typing import Optional, List
+
+import flask
+from flask import Request, Response
+import loguru
+from loguru import logger
+
+from monitoring.mock_uss import webapp
+
+
+def _get_request_id(req: Request) -> str:
+    return f"[{os.getpid()}] {req.date} {req.method} {req.url}"
+
+
+class RequestLogger(object):
+    _request_id: str
+    _loguru_hook: Optional[int] = None
+    _report_log: bool = True
+    messages: List[str]
+
+    def __init__(self):
+        self.messages = []
+
+    def add_to_loguru(self) -> None:
+        self._request_id = _get_request_id(flask.request)
+        self._loguru_hook = logger.add(
+            self.log,
+            format="[{time:YYYY-MM-DD HH:mm:ss.SSS} {level: <8} {name}:{function}:{line}] {message}",
+        )
+
+    def log(self, msg: loguru.Message) -> None:
+        if self._report_log and _get_request_id(flask.request) == self._request_id:
+            self.messages.append(msg)
+
+    def do_not_report(self) -> None:
+        self._report_log = False
+
+    def get_response(self, resp: Response) -> Response:
+        if self._report_log and resp.is_json and self.messages:
+            body = resp.json
+            if "log_messages" not in body:
+                body["log_messages"] = self.messages
+            resp.data = json.dumps(body)
+        return resp
+
+    def remove_from_loguru(self) -> None:
+        if self._loguru_hook is not None:
+            logger.remove(self._loguru_hook)
+            self._loguru_hook = None
+
+
+_REQUEST_LOGGER_FIELD = "request_logger"
+
+
+def get_request_logger() -> Optional[RequestLogger]:
+    if hasattr(flask.request, _REQUEST_LOGGER_FIELD):
+        return getattr(flask.request, _REQUEST_LOGGER_FIELD)
+    else:
+        return None
+
+
+def disable_log_reporting_for_request():
+    request_logger = get_request_logger()
+    if request_logger is not None:
+        request_logger.do_not_report()
+
+
+@webapp.before_request
+def begin_request_log() -> None:
+    request_logger = RequestLogger()
+    request_logger.add_to_loguru()
+    setattr(flask.request, _REQUEST_LOGGER_FIELD, request_logger)
+
+
+@webapp.after_request
+def add_request_log(resp: Response):
+    request_logger = get_request_logger()
+    if request_logger is not None:
+        return request_logger.get_response(resp)
+    else:
+        return resp
+
+
+@webapp.teardown_request
+def end_request_log(e: Optional[BaseException]) -> None:
+    request_logger = get_request_logger()
+    if request_logger is not None:
+        request_logger.remove_from_loguru()

monitoring/mock_uss/routes.py

@@ -4,6 +4,8 @@
 
 from monitoring.monitorlib import auth_validation, versioning
 from monitoring.mock_uss import webapp, enabled_services
+from monitoring.mock_uss.logging import disable_log_reporting_for_request
+from ..monitorlib.errors import stacktrace_string
 
 
 @webapp.route("/status")
@@ -23,6 +25,7 @@ def handle_exception(e):
     if isinstance(e, HTTPException):
         return e
     elif isinstance(e, auth_validation.InvalidScopeError):
+        disable_log_reporting_for_request()
         return (
             flask.jsonify(
                 {
@@ -33,6 +36,7 @@ def handle_exception(e):
             403,
         )
     elif isinstance(e, auth_validation.InvalidAccessTokenError):
+        disable_log_reporting_for_request()
         return flask.jsonify({"message": e.message}), 401
     elif isinstance(e, auth_validation.ConfigurationError):
         return (
@@ -43,10 +47,18 @@ def handle_exception(e):
         )
     elif isinstance(e, ValueError):
         traceback.print_exc()
-        return flask.jsonify({"message": str(e)}), 400
+        return (
+            flask.jsonify({"message": str(e), "stacktrace": stacktrace_string(e)}),
+            400,
+        )
     traceback.print_exc()
     return (
-        flask.jsonify({"message": "Unhandled {}: {}".format(type(e).__name__, str(e))}),
+        flask.jsonify(
+            {
+                "message": f"Unhandled {type(e).__name__}: {str(e)}",
+                "stacktrace": stacktrace_string(e),
+            }
+        ),
         500,
     )
 

monitoring/uss_qualifier/resources/interuss/mock_uss/client.py

@@ -102,7 +102,6 @@ def get_interactions(
         url = "{}/mock_uss/interuss_logging/logs?from_time={}".format(
             self.base_url, from_time
         )
-        logger.debug(f"Getting interactions from {from_time} : {url}")
         query = fetch.query_and_describe(
             self.session,
             "GET",