use new QueryStatistics in API server

src/nominatim_api/server/asgi_adaptor.py

@@ -2,7 +2,7 @@
 #
 # This file is part of Nominatim. (https://nominatim.org)
 #
-# Copyright (C) 2024 by the Nominatim developer community.
+# Copyright (C) 2025 by the Nominatim developer community.
 # For a full list of authors see the git log.
 """
 Base abstraction for implementing based on different ASGI frameworks.
@@ -13,6 +13,7 @@ import math
 
 from ..config import Configuration
 from ..core import NominatimAPIAsync
+from ..types import QueryStatistics
 from ..result_formatting import FormatDispatcher
 from .content_types import CONTENT_TEXT
 
@@ -68,6 +69,12 @@ class ASGIAdaptor(abc.ABC):
         """ Return the formatting object to use.
         """
 
+    @abc.abstractmethod
+    def query_stats(self) -> Optional[QueryStatistics]:
+        """ Return the object for saving query statistics or None if
+            no statistics are required.
+        """
+
     def get_int(self, name: str, default: Optional[int] = None) -> int:
         """ Return an input parameter as an int. Raises an exception if
             the parameter is given but not in an integer format.

src/nominatim_api/server/falcon/server.py

@@ -2,20 +2,21 @@
 #
 # This file is part of Nominatim. (https://nominatim.org)
 #
-# Copyright (C) 2024 by the Nominatim developer community.
+# Copyright (C) 2025 by the Nominatim developer community.
 # For a full list of authors see the git log.
 """
 Server implementation using the falcon webserver framework.
 """
-from typing import Optional, Mapping, Any, List
+from typing import Optional, Mapping, Any, List, cast
 from pathlib import Path
-import datetime as dt
 import asyncio
+import datetime as dt
 
 from falcon.asgi import App, Request, Response
 
 from ...config import Configuration
 from ...core import NominatimAPIAsync
+from ...types import QueryStatistics
 from ... import v1 as api_impl
 from ...result_formatting import FormatDispatcher, load_format_dispatcher
 from ... import logging as loglib
@@ -95,6 +96,9 @@ class ParamWrapper(ASGIAdaptor):
     def formatting(self) -> FormatDispatcher:
         return self._formatter
 
+    def query_stats(self) -> Optional[QueryStatistics]:
+        return cast(Optional[QueryStatistics], getattr(self.request.context, 'query_stats', None))
+
 
 class EndpointWrapper:
     """ Converter for server glue endpoint functions to Falcon request handlers.
@@ -124,7 +128,7 @@ class FileLoggingMiddleware:
     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)
+        req.context.query_stats = QueryStatistics()
 
     async def process_response(self, req: Request, resp: Response,
                                resource: Optional[EndpointWrapper],
@@ -132,19 +136,23 @@ class FileLoggingMiddleware:
         """ Callback after requests writes to the logfile. It only
             writes logs for successful requests for search, reverse and lookup.
         """
-        if not req_succeeded or resource is None or resp.status != 200\
+        qs = req.context.query_stats
+
+        if not req_succeeded or 'start' not in qs\
+           or resource is None or resp.status != 200\
            or resource.name not in ('reverse', 'search', 'lookup', 'details'):
             return
 
-        finish = dt.datetime.now(tz=dt.timezone.utc)
+        qs['endpoint'] = resource.name
-        duration = (finish - req.context.start).total_seconds()
+        qs['query_string'] = req.scope['query_string'].decode('utf8')
-        params = req.scope['query_string'].decode('utf8')
+        qs['results_total'] = getattr(resp.context, 'num_results', 0)
-        start = req.context.start.replace(tzinfo=None)\
+        for param in ('start', 'end', 'start_query'):
-                                 .isoformat(sep=' ', timespec='milliseconds')
+            if isinstance(qs.get(param), dt.datetime):
+                qs[param] = qs[param].replace(tzinfo=None)\
+                                     .isoformat(sep=' ', timespec='milliseconds')
 
-        self.fd.write(f"[{start}] "
+        self.fd.write(("[{start}] {total_time:.4f} {results_total} "
-                      f"{duration:.4f} {getattr(resp.context, 'num_results', 0)} "
+                       '{endpoint} "{query_string}"\n').format_map(qs))
-                      f'{resource.name} "{params}"\n')
 
 
 class APIMiddleware:

src/nominatim_api/server/starlette/server.py

@@ -2,7 +2,7 @@
 #
 # This file is part of Nominatim. (https://nominatim.org)
 #
-# Copyright (C) 2024 by the Nominatim developer community.
+# Copyright (C) 2025 by the Nominatim developer community.
 # For a full list of authors see the git log.
 """
 Server implementation using the starlette webserver framework.
@@ -10,9 +10,9 @@ Server implementation using the starlette webserver framework.
 from typing import Any, Optional, Mapping, Callable, cast, Coroutine, Dict, \
                    Awaitable, AsyncIterator
 from pathlib import Path
-import datetime as dt
 import asyncio
 import contextlib
+import datetime as dt
 
 from starlette.applications import Starlette
 from starlette.routing import Route
@@ -25,6 +25,7 @@ from starlette.middleware.cors import CORSMiddleware
 
 from ...config import Configuration
 from ...core import NominatimAPIAsync
+from ...types import QueryStatistics
 from ... import v1 as api_impl
 from ...result_formatting import FormatDispatcher, load_format_dispatcher
 from ..asgi_adaptor import ASGIAdaptor, EndpointFunc
@@ -70,6 +71,9 @@ class ParamWrapper(ASGIAdaptor):
     def formatting(self) -> FormatDispatcher:
         return cast(FormatDispatcher, self.request.app.state.formatter)
 
+    def query_stats(self) -> Optional[QueryStatistics]:
+        return cast(Optional[QueryStatistics], getattr(self.request.state, 'query_stats', None))
+
 
 def _wrap_endpoint(func: EndpointFunc)\
         -> Callable[[Request], Coroutine[Any, Any, Response]]:
@@ -89,27 +93,29 @@ class FileLoggingMiddleware(BaseHTTPMiddleware):
 
     async def dispatch(self, request: Request,
                        call_next: RequestResponseEndpoint) -> Response:
-        start = dt.datetime.now(tz=dt.timezone.utc)
+        qs = QueryStatistics()
+        request.state.query_stats = qs
         response = await call_next(request)
 
-        if response.status_code != 200:
+        if response.status_code != 200 or 'start' not in qs:
             return response
 
-        finish = dt.datetime.now(tz=dt.timezone.utc)
-
         for endpoint in ('reverse', 'search', 'lookup', 'details'):
             if request.url.path.startswith('/' + endpoint):
-                qtype = endpoint
+                qs['endpoint'] = endpoint
                 break
         else:
             return response
 
-        duration = (finish - start).total_seconds()
+        qs['query_string'] = request.scope['query_string'].decode('utf8')
-        params = request.scope['query_string'].decode('utf8')
+        qs['results_total'] = getattr(request.state, 'num_results', 0)
+        for param in ('start', 'end', 'start_query'):
+            if isinstance(qs.get(param), dt.datetime):
+                qs[param] = qs[param].replace(tzinfo=None)\
+                                     .isoformat(sep=' ', timespec='milliseconds')
 
-        self.fd.write(f"[{start.replace(tzinfo=None).isoformat(sep=' ', timespec='milliseconds')}] "
+        self.fd.write(("[{start}] {total_time:.4f} {results_total} "
-                      f"{duration:.4f} {getattr(request.state, 'num_results', 0)} "
+                       '{endpoint} "{query_string}"\n').format_map(qs))
-                      f'{qtype} "{params}"\n')
 
         return response
 

src/nominatim_api/types.py

@@ -340,18 +340,17 @@ class QueryStatistics(dict[str, Any]):
     """
 
     def __enter__(self) -> 'QueryStatistics':
-        self.log_time('start_function')
+        self.log_time('start')
         return self
 
     def __exit__(self, *_: Any) -> None:
-        self.log_time('end_function')
+        self.log_time('end')
-        self['total_time'] = (self['end_function'] - self['start_function']) \
+        self['total_time'] = (self['end'] - self['start']).total_seconds()
-            / dt.timedelta(microseconds=1)
         if 'start_query' in self:
-            self['wait_time'] = (self['start_query'] - self['start_function']) \
+            self['wait_time'] = (self['start_query'] - self['start']).total_seconds()
-                / dt.timedelta(microseconds=1)
         else:
-            self['wait_time'] = 0
+            self['wait_time'] = self['total_time']
+            self['start_query'] = self['end']
         self['query_time'] = self['total_time'] - self['wait_time']
 
     def __missing__(self, key: str) -> str:

src/nominatim_api/v1/server_glue.py

@@ -2,7 +2,7 @@
 #
 # This file is part of Nominatim. (https://nominatim.org)
 #
-# Copyright (C) 2024 by the Nominatim developer community.
+# Copyright (C) 2025 by the Nominatim developer community.
 # For a full list of authors see the git log.
 """
 Generic part of the server implementation of the v1 API.
@@ -165,6 +165,7 @@ async def details_endpoint(api: NominatimAPIAsync, params: ASGIAdaptor) -> Any:
                                geometry_output=(GeometryFormat.GEOJSON
                                                 if params.get_bool('polygon_geojson', False)
                                                 else GeometryFormat.NONE),
+                               query_stats=params.query_stats()
                                )
 
     if debug:
@@ -197,6 +198,7 @@ async def reverse_endpoint(api: NominatimAPIAsync, params: ASGIAdaptor) -> Any:
     details = parse_geometry_details(params, fmt)
     details['max_rank'] = helpers.zoom_to_rank(params.get_int('zoom', 18))
     details['layers'] = get_layers(params)
+    details['query_stats'] = params.query_stats()
 
     result = await api.reverse(coord, **details)
 
@@ -234,6 +236,7 @@ async def lookup_endpoint(api: NominatimAPIAsync, params: ASGIAdaptor) -> Any:
     fmt = parse_format(params, SearchResults, 'xml')
     debug = setup_debugging(params)
     details = parse_geometry_details(params, fmt)
+    details['query_stats'] = params.query_stats()
 
     places = []
     for oid in (params.get('osm_ids') or '').split(','):
@@ -302,6 +305,7 @@ async def search_endpoint(api: NominatimAPIAsync, params: ASGIAdaptor) -> Any:
     debug = setup_debugging(params)
     details = parse_geometry_details(params, fmt)
 
+    details['query_stats'] = params.query_stats()
     details['countries'] = params.get('countrycodes', None)
     details['entrances'] = params.get_bool('entrances', False)
     details['excluded'] = params.get('exclude_place_ids', None)

test/python/api/fake_adaptor.py

@@ -54,3 +54,6 @@ class FakeAdaptor(glue.ASGIAdaptor):
 
     def formatting(self):
         return formatting
+
+    def query_stats(self):
+        return None