diff --git a/monitoring/mock_uss/__init__.py b/monitoring/mock_uss/__init__.py index 5b44beac66..7e48df1357 100644 --- a/monitoring/mock_uss/__init__.py +++ b/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) diff --git a/monitoring/mock_uss/gunicorn.conf.py b/monitoring/mock_uss/gunicorn.conf.py index fbb3b140fd..15b424bc53 100644 --- a/monitoring/mock_uss/gunicorn.conf.py +++ b/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): diff --git a/monitoring/mock_uss/logging.py b/monitoring/mock_uss/logging.py new file mode 100644 index 0000000000..9f233ea713 --- /dev/null +++ b/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() diff --git a/monitoring/mock_uss/routes.py b/monitoring/mock_uss/routes.py index abac76a7e0..9680b0a351 100644 --- a/monitoring/mock_uss/routes.py +++ b/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, ) diff --git a/monitoring/uss_qualifier/resources/interuss/mock_uss/client.py b/monitoring/uss_qualifier/resources/interuss/mock_uss/client.py index e07567baef..86ffba1ffb 100644 --- a/monitoring/uss_qualifier/resources/interuss/mock_uss/client.py +++ b/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",