Merge pull request #3833 from lonvia/rework-logging

Introduce generic query statistics and make log output configurable
This commit is contained in:
Sarah Hoffmann
2025-09-11 08:46:44 +02:00
committed by GitHub
13 changed files with 248 additions and 85 deletions

View File

@@ -648,21 +648,53 @@ See also [NOMINATIM_DEFAULT_LANGUAGE](#nominatim_default_language).
| **Description:** | Log requests into a file | | **Description:** | Log requests into a file |
| **Format:** | path | | **Format:** | path |
| **Default:** | _empty_ (logging disabled) | | **Default:** | _empty_ (logging disabled) |
| **After Changes:** | run `nominatim refresh --website` |
Enable logging of requests into a file with this setting by setting the log Enable logging of requests into a file with this setting by setting the log
file where to log to. A relative file name is assumed to be relative to file where to log to. A relative file name is assumed to be relative to
the project directory. the project directory. The format of the log output can be set
with NOMINATIM_LOG_FORMAT.
#### NOMINATIM_LOG_FORMAT
The entries in the log file have the following format: | Summary | |
| -------------- | --------------------------------------------------- |
| **Description:** | Log requests into a file |
| **Format:** | [Python String Format](https://docs.python.org/3/library/string.html#formatstrings) string |
| **Default:** | `[{start}] {total_time:.4f} {results_total} {endpoint} "{query_string}"` |
<request time> <execution time in s> <number of results> <type> "<query string>" Describes the content of a log line for a single request. The format
must be readable by Python's format function. Nominatim provides a number
of metrics than can be logged. The default set of metrics is the following:
/// html | div.simple-table
| name | type | Description |
| --------------- | ------ | ------------|
| start | time | Point in time when the request arrived. |
| end | time | Point in time when the request was done. |
| query_start | time | Point in time when processing started. |
| total_time | float | Total time in seconds to handle the request. |
| wait_time | float | Time in seconds the request waited for a database connection to be available. |
| query_time | float | Total time in seconds to process the request once a connection was available. |
| results_total | int | Number of results found. |
| endpoint | string | API endpoint used. |
| query_string | string | Raw query string received. |
///
Variables of type 'time' contain a UTC timestamp string in ISO format.
Nominatim also exposes additional metrics to help with development. These
are subject to change between versions:
/// html | div.simple-table
| name | type | Description |
| ------------------------- | ------ | ------------|
| search_rounds | int | Total number of searches executed for the request. |
| search_min_penalty | float | Minimal possible penalty for the request. |
| search_first_result_round | int | Number of first search to yield any result. |
| search_min_result_penalty | float | Minimal penalty by a result found. |
| search_best_penalty_round | int | Search round that yielded the best penalty result. |
///
Request time is the time when the request was started. The execution time is
given in seconds and includes the entire time the query was queued and executed
in the frontend.
type contains the name of the endpoint used.
#### NOMINATIM_DEBUG_SQL #### NOMINATIM_DEBUG_SQL

View File

@@ -39,3 +39,9 @@ th {
filter: grayscale(100%); filter: grayscale(100%);
font-size: 80%; font-size: 80%;
} }
.simple-table table:not([class]) th,
.simple-table table:not([class]) td {
padding: 2px 4px;
background: white;
}

View File

@@ -67,6 +67,7 @@ markdown_extensions:
- codehilite - codehilite
- admonition - admonition
- pymdownx.superfences - pymdownx.superfences
- pymdownx.blocks.html
- pymdownx.tabbed: - pymdownx.tabbed:
alternate_style: true alternate_style: true
- def_list - def_list

View File

@@ -208,6 +208,13 @@ NOMINATIM_OUTPUT_NAMES=name:XX,name,brand,official_name:XX,short_name:XX,officia
# To enable logging set this setting to the file to log to. # To enable logging set this setting to the file to log to.
NOMINATIM_LOG_FILE= NOMINATIM_LOG_FILE=
# Set the output format of the query log.
# This is a string following the Python String Format syntax,
# see https://docs.python.org/3/library/string.html#formatstrings.
# For possible replacement values, see the full documentation at
# https://nominatim.org/release-docs/latest/customize/Settings/
NOMINATIM_LOG_FORMAT='[{start}] {total_time:.4f} {results_total} {endpoint} "{query_string}"'
# Echo raw SQL from SQLAlchemy statements. # Echo raw SQL from SQLAlchemy statements.
# EXPERT: Works only in command line/library use. # EXPERT: Works only in command line/library use.
NOMINATIM_DEBUG_SQL=no NOMINATIM_DEBUG_SQL=no

View File

@@ -24,7 +24,8 @@ from .types import (PlaceID as PlaceID,
Point as Point, Point as Point,
Bbox as Bbox, Bbox as Bbox,
GeometryFormat as GeometryFormat, GeometryFormat as GeometryFormat,
DataLayer as DataLayer) DataLayer as DataLayer,
QueryStatistics as QueryStatistics)
from .results import (SourceTable as SourceTable, from .results import (SourceTable as SourceTable,
AddressLine as AddressLine, AddressLine as AddressLine,
AddressLines as AddressLines, AddressLines as AddressLines,

View File

@@ -217,11 +217,13 @@ class NominatimAPIAsync:
""" """
timeout = Timeout(self.request_timeout) timeout = Timeout(self.request_timeout)
details = ntyp.LookupDetails.from_kwargs(params) details = ntyp.LookupDetails.from_kwargs(params)
async with self.begin(abs_timeout=timeout.abs) as conn: with details.query_stats as qs:
conn.set_query_timeout(self.query_timeout) async with self.begin(abs_timeout=timeout.abs) as conn:
if details.keywords: qs.log_time('start_query')
await nsearch.make_query_analyzer(conn) conn.set_query_timeout(self.query_timeout)
return await get_detailed_place(conn, place, details) if details.keywords:
await nsearch.make_query_analyzer(conn)
return await get_detailed_place(conn, place, details)
async def lookup(self, places: Sequence[ntyp.PlaceRef], **params: Any) -> SearchResults: async def lookup(self, places: Sequence[ntyp.PlaceRef], **params: Any) -> SearchResults:
""" Get simple information about a list of places. """ Get simple information about a list of places.
@@ -230,11 +232,13 @@ class NominatimAPIAsync:
""" """
timeout = Timeout(self.request_timeout) timeout = Timeout(self.request_timeout)
details = ntyp.LookupDetails.from_kwargs(params) details = ntyp.LookupDetails.from_kwargs(params)
async with self.begin(abs_timeout=timeout.abs) as conn: with details.query_stats as qs:
conn.set_query_timeout(self.query_timeout) async with self.begin(abs_timeout=timeout.abs) as conn:
if details.keywords: qs.log_time('start_query')
await nsearch.make_query_analyzer(conn) conn.set_query_timeout(self.query_timeout)
return await get_places(conn, places, details) if details.keywords:
await nsearch.make_query_analyzer(conn)
return await get_places(conn, places, details)
async def reverse(self, coord: ntyp.AnyPoint, **params: Any) -> Optional[ReverseResult]: async def reverse(self, coord: ntyp.AnyPoint, **params: Any) -> Optional[ReverseResult]:
""" Find a place by its coordinates. Also known as reverse geocoding. """ Find a place by its coordinates. Also known as reverse geocoding.
@@ -249,28 +253,32 @@ class NominatimAPIAsync:
timeout = Timeout(self.request_timeout) timeout = Timeout(self.request_timeout)
details = ntyp.ReverseDetails.from_kwargs(params) details = ntyp.ReverseDetails.from_kwargs(params)
async with self.begin(abs_timeout=timeout.abs) as conn: with details.query_stats as qs:
conn.set_query_timeout(self.query_timeout) async with self.begin(abs_timeout=timeout.abs) as conn:
if details.keywords: qs.log_time('start_query')
await nsearch.make_query_analyzer(conn) conn.set_query_timeout(self.query_timeout)
geocoder = ReverseGeocoder(conn, details, if details.keywords:
self.reverse_restrict_to_country_area) await nsearch.make_query_analyzer(conn)
return await geocoder.lookup(coord) geocoder = ReverseGeocoder(conn, details,
self.reverse_restrict_to_country_area)
return await geocoder.lookup(coord)
async def search(self, query: str, **params: Any) -> SearchResults: async def search(self, query: str, **params: Any) -> SearchResults:
""" Find a place by free-text search. Also known as forward geocoding. """ Find a place by free-text search. Also known as forward geocoding.
""" """
query = query.strip()
if not query:
raise UsageError('Nothing to search for.')
timeout = Timeout(self.request_timeout) timeout = Timeout(self.request_timeout)
async with self.begin(abs_timeout=timeout.abs) as conn: details = ntyp.SearchDetails.from_kwargs(params)
conn.set_query_timeout(self.query_timeout) with details.query_stats as qs:
geocoder = nsearch.ForwardGeocoder(conn, ntyp.SearchDetails.from_kwargs(params), query = query.strip()
timeout) if not query:
phrases = [nsearch.Phrase(nsearch.PHRASE_ANY, p.strip()) for p in query.split(',')] raise UsageError('Nothing to search for.')
return await geocoder.lookup(phrases)
async with self.begin(abs_timeout=timeout.abs) as conn:
qs.log_time('start_query')
conn.set_query_timeout(self.query_timeout)
geocoder = nsearch.ForwardGeocoder(conn, details, timeout)
phrases = [nsearch.Phrase(nsearch.PHRASE_ANY, p.strip()) for p in query.split(',')]
return await geocoder.lookup(phrases)
async def search_address(self, amenity: Optional[str] = None, async def search_address(self, amenity: Optional[str] = None,
street: Optional[str] = None, street: Optional[str] = None,
@@ -283,10 +291,8 @@ class NominatimAPIAsync:
""" Find an address using structured search. """ Find an address using structured search.
""" """
timeout = Timeout(self.request_timeout) timeout = Timeout(self.request_timeout)
async with self.begin(abs_timeout=timeout.abs) as conn: details = ntyp.SearchDetails.from_kwargs(params)
conn.set_query_timeout(self.query_timeout) with details.query_stats as qs:
details = ntyp.SearchDetails.from_kwargs(params)
phrases: List[nsearch.Phrase] = [] phrases: List[nsearch.Phrase] = []
if amenity: if amenity:
@@ -325,6 +331,9 @@ class NominatimAPIAsync:
if amenity: if amenity:
details.layers |= ntyp.DataLayer.POI details.layers |= ntyp.DataLayer.POI
async with self.begin(abs_timeout=timeout.abs) as conn:
qs.log_time('start_query')
conn.set_query_timeout(self.query_timeout)
geocoder = nsearch.ForwardGeocoder(conn, details, timeout) geocoder = nsearch.ForwardGeocoder(conn, details, timeout)
return await geocoder.lookup(phrases) return await geocoder.lookup(phrases)
@@ -335,22 +344,24 @@ class NominatimAPIAsync:
The near place may either be given as an unstructured search The near place may either be given as an unstructured search
query in itself or as coordinates. query in itself or as coordinates.
""" """
if not categories:
return SearchResults()
timeout = Timeout(self.request_timeout) timeout = Timeout(self.request_timeout)
details = ntyp.SearchDetails.from_kwargs(params) details = ntyp.SearchDetails.from_kwargs(params)
async with self.begin(abs_timeout=timeout.abs) as conn: with details.query_stats as qs:
conn.set_query_timeout(self.query_timeout) if not categories:
if near_query: return SearchResults()
phrases = [nsearch.Phrase(nsearch.PHRASE_ANY, p) for p in near_query.split(',')]
else:
phrases = []
if details.keywords:
await nsearch.make_query_analyzer(conn)
geocoder = nsearch.ForwardGeocoder(conn, details, timeout) async with self.begin(abs_timeout=timeout.abs) as conn:
return await geocoder.lookup_pois(categories, phrases) qs.log_time('start_query')
conn.set_query_timeout(self.query_timeout)
if near_query:
phrases = [nsearch.Phrase(nsearch.PHRASE_ANY, p) for p in near_query.split(',')]
else:
phrases = []
if details.keywords:
await nsearch.make_query_analyzer(conn)
geocoder = nsearch.ForwardGeocoder(conn, details, timeout)
return await geocoder.lookup_pois(categories, phrases)
class NominatimAPI: class NominatimAPI:
@@ -447,6 +458,8 @@ class NominatimAPI:
Only POI places can have parents. (Default: False) Only POI places can have parents. (Default: False)
keywords (bool): Add detailed information about the search terms keywords (bool): Add detailed information about the search terms
used for this place. used for this place.
query_stats (QueryStatistics): When given collects statistics
about the query execution.
Returns: Returns:
source_table (enum): Data source of the place. See below for possible values. source_table (enum): Data source of the place. See below for possible values.
@@ -529,6 +542,8 @@ class NominatimAPI:
Only POI places can have parents. (Default: False) Only POI places can have parents. (Default: False)
keywords (bool): Add detailed information about the search terms keywords (bool): Add detailed information about the search terms
used for this place. used for this place.
query_stats (QueryStatistics): When given collects statistics
about the query execution.
Returns: Returns:
source_table (enum): Data source of the place. See below for possible values. source_table (enum): Data source of the place. See below for possible values.
@@ -609,6 +624,8 @@ class NominatimAPI:
Only POI places can have parents. (Default: False) Only POI places can have parents. (Default: False)
keywords (bool): Add detailed information about the search terms keywords (bool): Add detailed information about the search terms
used for this place. used for this place.
query_stats (QueryStatistics): When given collects statistics
about the query execution.
Returns: Returns:
source_table (enum): Data source of the place. See below for possible values. source_table (enum): Data source of the place. See below for possible values.
@@ -708,6 +725,8 @@ class NominatimAPI:
Only POI places can have parents. (Default: False) Only POI places can have parents. (Default: False)
keywords (bool): Add detailed information about the search terms keywords (bool): Add detailed information about the search terms
used for this place. used for this place.
query_stats (QueryStatistics): When given collects statistics
about the query execution.
Returns: Returns:
source_table (enum): Data source of the place. See below for possible values. source_table (enum): Data source of the place. See below for possible values.
@@ -824,6 +843,8 @@ class NominatimAPI:
Only POI places can have parents. (Default: False) Only POI places can have parents. (Default: False)
keywords (bool): Add detailed information about the search terms keywords (bool): Add detailed information about the search terms
used for this place. used for this place.
query_stats (QueryStatistics): When given collects statistics
about the query execution.
Returns: Returns:
source_table (enum): Data source of the place. See below for possible values. source_table (enum): Data source of the place. See below for possible values.
@@ -931,6 +952,8 @@ class NominatimAPI:
Only POI places can have parents. (Default: False) Only POI places can have parents. (Default: False)
keywords (bool): Add detailed information about the search terms keywords (bool): Add detailed information about the search terms
used for this place. used for this place.
query_stats (QueryStatistics): When given collects statistics
about the query execution.
Returns: Returns:
source_table (enum): Data source of the place. See below for possible values. source_table (enum): Data source of the place. See below for possible values.

View File

@@ -77,7 +77,9 @@ class ForwardGeocoder:
""" """
log().section('Execute database searches') log().section('Execute database searches')
results: Dict[Any, SearchResult] = {} results: Dict[Any, SearchResult] = {}
qs = self.params.query_stats
qs['search_min_penalty'] = round(searches[0].penalty, 2)
min_ranking = searches[0].penalty + 2.0 min_ranking = searches[0].penalty + 2.0
prev_penalty = 0.0 prev_penalty = 0.0
for i, search in enumerate(searches): for i, search in enumerate(searches):
@@ -93,6 +95,13 @@ class ForwardGeocoder:
if prevresult: if prevresult:
prevresult.accuracy = min(prevresult.accuracy, result.accuracy) prevresult.accuracy = min(prevresult.accuracy, result.accuracy)
else: else:
if not results:
qs['search_first_result_round'] = i
spenalty = round(search.penalty, 2)
if 'search_min_result_penalty' not in qs or \
spenalty < qs['search_min_result_penalty']:
qs['search_min_result_penalty'] = spenalty
qs['search_best_penalty_round'] = i
results[rhash] = result results[rhash] = result
min_ranking = min(min_ranking, result.accuracy * 1.2, 2.0) min_ranking = min(min_ranking, result.accuracy * 1.2, 2.0)
log().result_dump('Results', ((r.accuracy, r) for r in lookup_results)) log().result_dump('Results', ((r.accuracy, r) for r in lookup_results))
@@ -100,6 +109,7 @@ class ForwardGeocoder:
if self.timeout.is_elapsed(): if self.timeout.is_elapsed():
break break
qs['search_rounds'] = i
return SearchResults(results.values()) return SearchResults(results.values())
def pre_filter_results(self, results: SearchResults) -> SearchResults: def pre_filter_results(self, results: SearchResults) -> SearchResults:

View File

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

View File

@@ -2,20 +2,21 @@
# #
# This file is part of Nominatim. (https://nominatim.org) # 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. # For a full list of authors see the git log.
""" """
Server implementation using the falcon webserver framework. 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 from pathlib import Path
import datetime as dt
import asyncio import asyncio
import datetime as dt
from falcon.asgi import App, Request, Response from falcon.asgi import App, Request, Response
from ...config import Configuration from ...config import Configuration
from ...core import NominatimAPIAsync from ...core import NominatimAPIAsync
from ...types import QueryStatistics
from ... import v1 as api_impl from ... import v1 as api_impl
from ...result_formatting import FormatDispatcher, load_format_dispatcher from ...result_formatting import FormatDispatcher, load_format_dispatcher
from ... import logging as loglib from ... import logging as loglib
@@ -95,6 +96,9 @@ class ParamWrapper(ASGIAdaptor):
def formatting(self) -> FormatDispatcher: def formatting(self) -> FormatDispatcher:
return self._formatter return self._formatter
def query_stats(self) -> Optional[QueryStatistics]:
return cast(Optional[QueryStatistics], getattr(self.request.context, 'query_stats', None))
class EndpointWrapper: class EndpointWrapper:
""" Converter for server glue endpoint functions to Falcon request handlers. """ Converter for server glue endpoint functions to Falcon request handlers.
@@ -118,13 +122,14 @@ class FileLoggingMiddleware:
""" Middleware to log selected requests into a file. """ Middleware to log selected requests into a file.
""" """
def __init__(self, file_name: str): def __init__(self, file_name: str, logstr: str):
self.logstr = logstr + '\n'
self.fd = open(file_name, 'a', buffering=1, encoding='utf8') self.fd = open(file_name, 'a', buffering=1, encoding='utf8')
async def process_request(self, req: Request, _: Response) -> None: async def process_request(self, req: Request, _: Response) -> None:
""" Callback before the request starts timing. """ 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, async def process_response(self, req: Request, resp: Response,
resource: Optional[EndpointWrapper], resource: Optional[EndpointWrapper],
@@ -132,19 +137,22 @@ class FileLoggingMiddleware:
""" Callback after requests writes to the logfile. It only """ Callback after requests writes to the logfile. It only
writes logs for successful requests for search, reverse and lookup. 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'): or resource.name not in ('reverse', 'search', 'lookup', 'details'):
return 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(self.logstr.format_map(qs))
f"{duration:.4f} {getattr(resp.context, 'num_results', 0)} "
f'{resource.name} "{params}"\n')
class APIMiddleware: class APIMiddleware:
@@ -193,7 +201,7 @@ def get_application(project_dir: Path,
middleware: List[Any] = [apimw] middleware: List[Any] = [apimw]
log_file = apimw.config.LOG_FILE log_file = apimw.config.LOG_FILE
if log_file: if log_file:
middleware.append(FileLoggingMiddleware(log_file)) middleware.append(FileLoggingMiddleware(log_file, apimw.config.LOG_FORMAT))
app = App(cors_enable=apimw.config.get_bool('CORS_NOACCESSCONTROL'), app = App(cors_enable=apimw.config.get_bool('CORS_NOACCESSCONTROL'),
middleware=middleware) middleware=middleware)

View File

@@ -2,7 +2,7 @@
# #
# This file is part of Nominatim. (https://nominatim.org) # 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. # For a full list of authors see the git log.
""" """
Server implementation using the starlette webserver framework. 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, \ from typing import Any, Optional, Mapping, Callable, cast, Coroutine, Dict, \
Awaitable, AsyncIterator Awaitable, AsyncIterator
from pathlib import Path from pathlib import Path
import datetime as dt
import asyncio import asyncio
import contextlib import contextlib
import datetime as dt
from starlette.applications import Starlette from starlette.applications import Starlette
from starlette.routing import Route from starlette.routing import Route
@@ -25,6 +25,7 @@ from starlette.middleware.cors import CORSMiddleware
from ...config import Configuration from ...config import Configuration
from ...core import NominatimAPIAsync from ...core import NominatimAPIAsync
from ...types import QueryStatistics
from ... import v1 as api_impl from ... import v1 as api_impl
from ...result_formatting import FormatDispatcher, load_format_dispatcher from ...result_formatting import FormatDispatcher, load_format_dispatcher
from ..asgi_adaptor import ASGIAdaptor, EndpointFunc from ..asgi_adaptor import ASGIAdaptor, EndpointFunc
@@ -70,6 +71,9 @@ class ParamWrapper(ASGIAdaptor):
def formatting(self) -> FormatDispatcher: def formatting(self) -> FormatDispatcher:
return cast(FormatDispatcher, self.request.app.state.formatter) 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)\ def _wrap_endpoint(func: EndpointFunc)\
-> Callable[[Request], Coroutine[Any, Any, Response]]: -> Callable[[Request], Coroutine[Any, Any, Response]]:
@@ -83,33 +87,35 @@ class FileLoggingMiddleware(BaseHTTPMiddleware):
""" Middleware to log selected requests into a file. """ Middleware to log selected requests into a file.
""" """
def __init__(self, app: Starlette, file_name: str = ''): def __init__(self, app: Starlette, file_name: str = '', logstr: str = ''):
super().__init__(app) super().__init__(app)
self.fd = open(file_name, 'a', buffering=1, encoding='utf8') self.fd = open(file_name, 'a', buffering=1, encoding='utf8')
self.logstr = logstr + '\n'
async def dispatch(self, request: Request, async def dispatch(self, request: Request,
call_next: RequestResponseEndpoint) -> Response: call_next: RequestResponseEndpoint) -> Response:
start = dt.datetime.now(tz=dt.timezone.utc) qs = QueryStatistics()
request.state.query_stats = qs
response = await call_next(request) response = await call_next(request)
if response.status_code != 200: if response.status_code != 200 or 'start' not in qs:
return response return response
finish = dt.datetime.now(tz=dt.timezone.utc)
for endpoint in ('reverse', 'search', 'lookup', 'details'): for endpoint in ('reverse', 'search', 'lookup', 'details'):
if request.url.path.startswith('/' + endpoint): if request.url.path.startswith('/' + endpoint):
qtype = endpoint qs['endpoint'] = endpoint
break break
else: else:
return response 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(self.logstr.format_map(qs))
f"{duration:.4f} {getattr(request.state, 'num_results', 0)} "
f'{qtype} "{params}"\n')
return response return response
@@ -143,7 +149,8 @@ def get_application(project_dir: Path,
log_file = config.LOG_FILE log_file = config.LOG_FILE
if log_file: if log_file:
middleware.append(Middleware(FileLoggingMiddleware, file_name=log_file)) # type: ignore middleware.append(Middleware(FileLoggingMiddleware, file_name=log_file, # type: ignore
logstr=config.LOG_FORMAT))
exceptions: Dict[Any, Callable[[Request, Exception], Awaitable[Response]]] = { exceptions: Dict[Any, Callable[[Request, Exception], Awaitable[Response]]] = {
TimeoutError: timeout_error, TimeoutError: timeout_error,

View File

@@ -2,7 +2,7 @@
# #
# This file is part of Nominatim. (https://nominatim.org) # 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. # For a full list of authors see the git log.
""" """
Complex datatypes used by the Nominatim API. Complex datatypes used by the Nominatim API.
@@ -11,6 +11,7 @@ from typing import Optional, Union, Tuple, NamedTuple, TypeVar, Type, Dict, \
Any, List, Sequence Any, List, Sequence
from collections import abc from collections import abc
import dataclasses import dataclasses
import datetime as dt
import enum import enum
import math import math
from struct import unpack from struct import unpack
@@ -334,6 +335,54 @@ class DataLayer(enum.Flag):
""" """
class QueryStatistics(dict[str, Any]):
""" A specialised dictionary for collecting query statistics.
"""
def __enter__(self) -> 'QueryStatistics':
self.log_time('start')
return self
def __exit__(self, *_: Any) -> None:
self.log_time('end')
self['total_time'] = (self['end'] - self['start']).total_seconds()
if 'start_query' in self:
self['wait_time'] = (self['start_query'] - self['start']).total_seconds()
else:
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:
return ''
def log_time(self, key: str) -> None:
self[key] = dt.datetime.now(tz=dt.timezone.utc)
class NoQueryStats:
""" Null object to use, when no query statistics are requested.
"""
def __enter__(self) -> 'NoQueryStats':
return self
def __exit__(self, *_: Any) -> None:
pass
def __setitem__(self, key: str, value: Any) -> None:
pass
def __getitem__(self, key: str) -> Any:
return None
def __contains__(self, key: str, default: Any = None) -> bool:
return False
def log_time(self, key: str) -> None:
pass
def format_country(cc: Any) -> List[str]: def format_country(cc: Any) -> List[str]:
""" Extract a list of country codes from the input which may be either """ Extract a list of country codes from the input which may be either
a string or list of strings. Filters out all values that are not a string or list of strings. Filters out all values that are not
@@ -412,6 +461,11 @@ class LookupDetails:
0.0 means the original geometry is kept. The higher the value, the 0.0 means the original geometry is kept. The higher the value, the
more the geometry gets simplified. more the geometry gets simplified.
""" """
query_stats: Union[QueryStatistics, NoQueryStats] = \
dataclasses.field(default_factory=NoQueryStats)
""" Optional QueryStatistics object collecting information about
runtime behaviour of the call.
"""
@classmethod @classmethod
def from_kwargs(cls: Type[TParam], kwargs: Dict[str, Any]) -> TParam: def from_kwargs(cls: Type[TParam], kwargs: Dict[str, Any]) -> TParam:

View File

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

View File

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