reintroduce file logging for Python frontend

diff --git a/nominatim/api/v1/server_glue.py b/nominatim/api/v1/server_glue.py
index 5ebdb55e967a29e94966213dc9613df7d1180d08..d83adaae646d51f5ca03750e545d91b6eae68db1 100644 (file)
--- a/nominatim/api/v1/server_glue.py
+++ b/nominatim/api/v1/server_glue.py
@@ -58,7 +58,7 @@ class ASGIAdaptor(abc.ABC):
 
 
     @abc.abstractmethod
 
 
     @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
         """ 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.
         """
         """ 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'
 
                 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:
 
 
     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})
 
                   '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:
 
 
 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:
     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'}
 
     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)
 
     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:
 
 
 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:
         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),
 
     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)
 
 
     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,
 
 
 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:
         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,
 
     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)
 
 
     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:
 
 
 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 c11cf4a845de734f1f68319990ebb6b179ca40d1..196c519f014212a6a96fe68244d32dada97256c9 100644 (file)
--- 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
 """
 from typing import Optional, Mapping, cast, Any
 from pathlib import Path

+import datetime as dt

 
 from falcon.asgi import App, Request, Response
 
 
 from falcon.asgi import App, Request, Response
 


@@ -59,7 +60,8 @@ class ParamWrapper(api_impl.ASGIAdaptor):
         return HTTPNominatimError(msg, status, self.content_type)
 
 
         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
         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.
     """
 
     """ 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
 
         self.func = func
         self.api = api
 


@@ -84,18 +87,59 @@ class EndpointWrapper:
         await self.func(self.api, ParamWrapper(req, resp, self.api.config))
 
 
         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)
 
 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:
     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)
         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 f81b122f274e17ddf0e0565139b09e003663a05e..2bcc8df51c37b0bb8ad00316551903fc6ad728ed 100644 (file)
--- 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
 """
 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
 
 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.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
 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})
 
 
                              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)
 
 
         return Response(output, status_code=status, media_type=self.content_type)
 
 


@@ -59,6 +62,41 @@ def _wrap_endpoint(func: api_impl.EndpointFunc)\
     return _callback
 
 
     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:
 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=['*']))
 
     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()
 
     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 1db8c72580a4baa3da1af9480549dda86b9449c0..f04381db2ad2683bf7e8dbe41dd28752617b7051 100644 (file)
--- 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)
 
 
         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)
 
 
         return FakeResponse(status, output, self.content_type)