From e523da9e12ad87b945a7b5add83618258ccf1efb Mon Sep 17 00:00:00 2001 From: Sarah Hoffmann Date: Sun, 30 Jul 2023 19:58:00 +0200 Subject: [PATCH] reintroduce file logging for Python frontend --- nominatim/api/v1/server_glue.py | 20 +++++------ nominatim/server/falcon/server.py | 52 +++++++++++++++++++++++++--- nominatim/server/starlette/server.py | 44 ++++++++++++++++++++++- test/python/api/fake_adaptor.py | 2 +- 4 files changed, 102 insertions(+), 16 deletions(-) diff --git a/nominatim/api/v1/server_glue.py b/nominatim/api/v1/server_glue.py index 5ebdb55e..d83adaae 100644 --- a/nominatim/api/v1/server_glue.py +++ b/nominatim/api/v1/server_glue.py @@ -58,7 +58,7 @@ class ASGIAdaptor(abc.ABC): @abc.abstractmethod - def create_response(self, status: int, output: str) -> Any: + def create_response(self, status: int, output: str, num_results: int) -> Any: """ Create a response from the given parameters. The result will be returned by the endpoint functions. The adaptor may also return None when the response is created internally with some @@ -76,7 +76,7 @@ class ASGIAdaptor(abc.ABC): """ - def build_response(self, output: str, status: int = 200) -> Any: + def build_response(self, output: str, status: int = 200, num_results: int = 0) -> Any: """ Create a response from the given output. Wraps a JSONP function around the response, if necessary. """ @@ -88,7 +88,7 @@ class ASGIAdaptor(abc.ABC): output = f"{jsonp}({output})" self.content_type = 'application/javascript' - return self.create_response(status, output) + return self.create_response(status, output, num_results) def raise_error(self, msg: str, status: int = 400) -> NoReturn: @@ -318,7 +318,7 @@ async def details_endpoint(api: napi.NominatimAPIAsync, params: ASGIAdaptor) -> 'group_hierarchy': params.get_bool('group_hierarchy', False), 'icon_base_url': params.config().MAPICON_URL}) - return params.build_response(output) + return params.build_response(output, num_results=1) async def reverse_endpoint(api: napi.NominatimAPIAsync, params: ASGIAdaptor) -> Any: @@ -335,7 +335,7 @@ async def reverse_endpoint(api: napi.NominatimAPIAsync, params: ASGIAdaptor) -> result = await api.reverse(coord, **details) if debug: - return params.build_response(loglib.get_and_disable()) + return params.build_response(loglib.get_and_disable(), num_results=1 if result else 0) if fmt == 'xml': queryparts = {'lat': str(coord.lat), 'lon': str(coord.lon), 'format': 'xml'} @@ -357,7 +357,7 @@ async def reverse_endpoint(api: napi.NominatimAPIAsync, params: ASGIAdaptor) -> output = formatting.format_result(napi.ReverseResults([result] if result else []), fmt, fmt_options) - return params.build_response(output) + return params.build_response(output, num_results=1 if result else 0) async def lookup_endpoint(api: napi.NominatimAPIAsync, params: ASGIAdaptor) -> Any: @@ -382,7 +382,7 @@ async def lookup_endpoint(api: napi.NominatimAPIAsync, params: ASGIAdaptor) -> A results = napi.SearchResults() if debug: - return params.build_response(loglib.get_and_disable()) + return params.build_response(loglib.get_and_disable(), num_results=len(results)) fmt_options = {'extratags': params.get_bool('extratags', False), 'namedetails': params.get_bool('namedetails', False), @@ -392,7 +392,7 @@ async def lookup_endpoint(api: napi.NominatimAPIAsync, params: ASGIAdaptor) -> A output = formatting.format_result(results, fmt, fmt_options) - return params.build_response(output) + return params.build_response(output, num_results=len(results)) async def _unstructured_search(query: str, api: napi.NominatimAPIAsync, @@ -471,7 +471,7 @@ async def search_endpoint(api: napi.NominatimAPIAsync, params: ASGIAdaptor) -> A results = helpers.deduplicate_results(results, max_results) if debug: - return params.build_response(loglib.get_and_disable()) + return params.build_response(loglib.get_and_disable(), num_results=len(results)) if fmt == 'xml': helpers.extend_query_parts(queryparts, details, @@ -494,7 +494,7 @@ async def search_endpoint(api: napi.NominatimAPIAsync, params: ASGIAdaptor) -> A output = formatting.format_result(results, fmt, fmt_options) - return params.build_response(output) + return params.build_response(output, num_results=len(results)) async def deletable_endpoint(api: napi.NominatimAPIAsync, params: ASGIAdaptor) -> Any: diff --git a/nominatim/server/falcon/server.py b/nominatim/server/falcon/server.py index c11cf4a8..196c519f 100644 --- a/nominatim/server/falcon/server.py +++ b/nominatim/server/falcon/server.py @@ -9,6 +9,7 @@ Server implementation using the falcon webserver framework. """ from typing import Optional, Mapping, cast, Any from pathlib import Path +import datetime as dt from falcon.asgi import App, Request, Response @@ -59,7 +60,8 @@ class ParamWrapper(api_impl.ASGIAdaptor): return HTTPNominatimError(msg, status, self.content_type) - def create_response(self, status: int, output: str) -> None: + def create_response(self, status: int, output: str, num_results: int) -> None: + self.response.context.num_results = num_results self.response.status = status self.response.text = output self.response.content_type = self.content_type @@ -73,7 +75,8 @@ class EndpointWrapper: """ Converter for server glue endpoint functions to Falcon request handlers. """ - def __init__(self, func: api_impl.EndpointFunc, api: NominatimAPIAsync) -> None: + def __init__(self, name: str, func: api_impl.EndpointFunc, api: NominatimAPIAsync) -> None: + self.name = name self.func = func self.api = api @@ -84,18 +87,59 @@ class EndpointWrapper: await self.func(self.api, ParamWrapper(req, resp, self.api.config)) +class FileLoggingMiddleware: + """ Middleware to log selected requests into a file. + """ + + def __init__(self, file_name: str): + self.fd = open(file_name, 'a', buffering=1, encoding='utf8') # pylint: disable=R1732 + + + async def process_request(self, req: Request, _: Response) -> None: + """ Callback before the request starts timing. + """ + req.context.start = dt.datetime.now(tz=dt.timezone.utc) + + + async def process_response(self, req: Request, resp: Response, + resource: Optional[EndpointWrapper], + req_succeeded: bool) -> None: + """ Callback after requests writes to the logfile. It only + writes logs for sucessful requests for search, reverse and lookup. + """ + if not req_succeeded or resource is None or resp.status != 200\ + or resource.name not in ('reverse', 'search', 'lookup'): + return + + finish = dt.datetime.now(tz=dt.timezone.utc) + duration = (finish - req.context.start).total_seconds() + params = req.scope['query_string'].decode('utf8') + start = req.context.start.replace(tzinfo=None)\ + .isoformat(sep=' ', timespec='milliseconds') + + self.fd.write(f"[{start}] " + f"{duration:.4f} {getattr(resp.context, 'num_results', 0)} " + f'{resource.name} "{params}"\n') + + def get_application(project_dir: Path, environ: Optional[Mapping[str, str]] = None) -> App: """ Create a Nominatim Falcon ASGI application. """ api = NominatimAPIAsync(project_dir, environ) - app = App(cors_enable=api.config.get_bool('CORS_NOACCESSCONTROL')) + middleware: Optional[object] = None + log_file = api.config.LOG_FILE + if log_file: + middleware = FileLoggingMiddleware(log_file) + + app = App(cors_enable=api.config.get_bool('CORS_NOACCESSCONTROL'), + middleware=middleware) app.add_error_handler(HTTPNominatimError, nominatim_error_handler) legacy_urls = api.config.get_bool('SERVE_LEGACY_URLS') for name, func in api_impl.ROUTES: - endpoint = EndpointWrapper(func, api) + endpoint = EndpointWrapper(name, func, api) app.add_route(f"/{name}", endpoint) if legacy_urls: app.add_route(f"/{name}.php", endpoint) diff --git a/nominatim/server/starlette/server.py b/nominatim/server/starlette/server.py index f81b122f..2bcc8df5 100644 --- a/nominatim/server/starlette/server.py +++ b/nominatim/server/starlette/server.py @@ -9,6 +9,7 @@ Server implementation using the starlette webserver framework. """ from typing import Any, Optional, Mapping, Callable, cast, Coroutine from pathlib import Path +import datetime as dt from starlette.applications import Starlette from starlette.routing import Route @@ -16,6 +17,7 @@ from starlette.exceptions import HTTPException from starlette.responses import Response from starlette.requests import Request from starlette.middleware import Middleware +from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint from starlette.middleware.cors import CORSMiddleware from nominatim.api import NominatimAPIAsync @@ -43,7 +45,8 @@ class ParamWrapper(api_impl.ASGIAdaptor): headers={'content-type': self.content_type}) - def create_response(self, status: int, output: str) -> Response: + def create_response(self, status: int, output: str, num_results: int) -> Response: + self.request.state.num_results = num_results return Response(output, status_code=status, media_type=self.content_type) @@ -59,6 +62,41 @@ def _wrap_endpoint(func: api_impl.EndpointFunc)\ return _callback +class FileLoggingMiddleware(BaseHTTPMiddleware): + """ Middleware to log selected requests into a file. + """ + + def __init__(self, app: Starlette, file_name: str = ''): + super().__init__(app) + self.fd = open(file_name, 'a', buffering=1, encoding='utf8') # pylint: disable=R1732 + + async def dispatch(self, request: Request, + call_next: RequestResponseEndpoint) -> Response: + start = dt.datetime.now(tz=dt.timezone.utc) + response = await call_next(request) + + if response.status_code != 200: + return response + + finish = dt.datetime.now(tz=dt.timezone.utc) + + for endpoint in ('reverse', 'search', 'lookup'): + if request.url.path.startswith('/' + endpoint): + qtype = endpoint + break + else: + return response + + duration = (finish - start).total_seconds() + params = request.scope['query_string'].decode('utf8') + + self.fd.write(f"[{start.replace(tzinfo=None).isoformat(sep=' ', timespec='milliseconds')}] " + f"{duration:.4f} {getattr(request.state, 'num_results', 0)} " + f'{qtype} "{params}"\n') + + return response + + def get_application(project_dir: Path, environ: Optional[Mapping[str, str]] = None, debug: bool = True) -> Starlette: @@ -78,6 +116,10 @@ def get_application(project_dir: Path, if config.get_bool('CORS_NOACCESSCONTROL'): middleware.append(Middleware(CORSMiddleware, allow_origins=['*'])) + log_file = config.LOG_FILE + if log_file: + middleware.append(Middleware(FileLoggingMiddleware, file_name=log_file)) + async def _shutdown() -> None: await app.state.API.close() diff --git a/test/python/api/fake_adaptor.py b/test/python/api/fake_adaptor.py index 1db8c725..f04381db 100644 --- a/test/python/api/fake_adaptor.py +++ b/test/python/api/fake_adaptor.py @@ -43,7 +43,7 @@ class FakeAdaptor(glue.ASGIAdaptor): return FakeError(msg, status) - def create_response(self, status, output): + def create_response(self, status, output, num_results): return FakeResponse(status, output, self.content_type) -- 2.45.1