src/nominatim_api/logging.py

   1 # SPDX-License-Identifier: GPL-3.0-or-later
   2 #
   3 # This file is part of Nominatim. (https://nominatim.org)
   4 #
   5 # Copyright (C) 2025 by the Nominatim developer community.
   6 # For a full list of authors see the git log.
   7 """
   8 Functions for specialised logging with HTML output.
   9 """
  10 from typing import Any, Iterator, Optional, List, Tuple, cast, Union, Mapping, Sequence
  11 from contextvars import ContextVar
  12 import datetime as dt
  13 import textwrap
  14 import io
  15 import re
  16 import html
  17
  18 import sqlalchemy as sa
  19 from sqlalchemy.ext.asyncio import AsyncConnection
  20
  21 try:
  22     from pygments import highlight
  23     from pygments.lexers import PythonLexer, PostgresLexer
  24     from pygments.formatters import HtmlFormatter
  25     CODE_HIGHLIGHT = True
  26 except ModuleNotFoundError:
  27     CODE_HIGHLIGHT = False
  28
  29
  30 def _debug_name(res: Any) -> str:
  31     if res.names:
  32         return cast(str, res.names.get('name', next(iter(res.names.values()))))
  33
  34     return f"Hnr {res.housenumber}" if res.housenumber is not None else '[NONE]'
  35
  36
  37 class BaseLogger:
  38     """ Interface for logging function.
  39
  40         The base implementation does nothing. Overwrite the functions
  41         in derived classes which implement logging functionality.
  42     """
  43     def get_buffer(self) -> str:
  44         """ Return the current content of the log buffer.
  45         """
  46         return ''
  47
  48     def function(self, func: str, **kwargs: Any) -> None:
  49         """ Start a new debug chapter for the given function and its parameters.
  50         """
  51
  52     def section(self, heading: str) -> None:
  53         """ Start a new section with the given title.
  54         """
  55
  56     def comment(self, text: str) -> None:
  57         """ Add a simple comment to the debug output.
  58         """
  59
  60     def var_dump(self, heading: str, var: Any) -> None:
  61         """ Print the content of the variable to the debug output prefixed by
  62             the given heading.
  63         """
  64
  65     def table_dump(self, heading: str, rows: Iterator[Optional[List[Any]]]) -> None:
  66         """ Print the table generated by the generator function.
  67         """
  68
  69     def result_dump(self, heading: str, results: Iterator[Tuple[Any, Any]]) -> None:
  70         """ Print a list of search results generated by the generator function.
  71         """
  72
  73     def sql(self, conn: AsyncConnection, statement: 'sa.Executable',
  74             params: Union[Mapping[str, Any], Sequence[Mapping[str, Any]], None]) -> None:
  75         """ Print the SQL for the given statement.
  76         """
  77
  78     def format_sql(self, conn: AsyncConnection, statement: 'sa.Executable',
  79                    extra_params: Union[Mapping[str, Any], Sequence[Mapping[str, Any]], None]
  80                    ) -> str:
  81         """ Return the compiled version of the statement.
  82         """
  83         compiled = cast('sa.ClauseElement', statement).compile(conn.sync_engine)
  84
  85         params = dict(compiled.params)
  86         if isinstance(extra_params, Mapping):
  87             for k, v in extra_params.items():
  88                 if hasattr(v, 'to_wkt'):
  89                     params[k] = v.to_wkt()
  90                 elif isinstance(v, (int, float)):
  91                     params[k] = v
  92                 else:
  93                     params[k] = str(v)
  94         elif isinstance(extra_params, Sequence) and extra_params:
  95             for k in extra_params[0]:
  96                 params[k] = f':{k}'
  97
  98         sqlstr = str(compiled)
  99
 100         if conn.dialect.name == 'postgresql':
 101             if sa.__version__.startswith('1'):
 102                 try:
 103                     sqlstr = re.sub(r'__\[POSTCOMPILE_[^]]*\]', '%s', sqlstr)
 104                     return sqlstr % tuple((repr(params.get(name, None))
 105                                           for name in compiled.positiontup))  # type: ignore
 106                 except TypeError:
 107                     return sqlstr
 108
 109             sqlstr = re.sub(r'__\[POSTCOMPILE_([^]]*)\]', r'%(\1)s', sqlstr)
 110             return sqlstr % params
 111
 112         assert conn.dialect.name == 'sqlite'
 113
 114         # params in positional order
 115         pparams = (repr(params.get(name, None)) for name in compiled.positiontup)  # type: ignore
 116
 117         sqlstr = re.sub(r'__\[POSTCOMPILE_([^]]*)\]', '?', sqlstr)
 118         sqlstr = re.sub(r"\?", lambda m: next(pparams), sqlstr)
 119
 120         return sqlstr
 121
 122
 123 class HTMLLogger(BaseLogger):
 124     """ Logger that formats messages in HTML.
 125     """
 126     def __init__(self) -> None:
 127         self.buffer = io.StringIO()
 128
 129     def _timestamp(self) -> None:
 130         self._write(f'<p class="timestamp">[{dt.datetime.now()}]</p>')
 131
 132     def get_buffer(self) -> str:
 133         return HTML_HEADER + self.buffer.getvalue() + HTML_FOOTER
 134
 135     def function(self, func: str, **kwargs: Any) -> None:
 136         self._timestamp()
 137         self._write(f"<h1>Debug output for {func}()</h1>\n<p>Parameters:<dl>")
 138         for name, value in kwargs.items():
 139             self._write(f'<dt>{name}</dt><dd>{self._python_var(value)}</dd>')
 140         self._write('</dl></p>')
 141
 142     def section(self, heading: str) -> None:
 143         self._timestamp()
 144         self._write(f"<h2>{heading}</h2>")
 145
 146     def comment(self, text: str) -> None:
 147         self._timestamp()
 148         self._write(f"<p>{text}</p>")
 149
 150     def var_dump(self, heading: str, var: Any) -> None:
 151         self._timestamp()
 152         if callable(var):
 153             var = var()
 154
 155         self._write(f'<h5>{heading}</h5>{self._python_var(var)}')
 156
 157     def table_dump(self, heading: str, rows: Iterator[Optional[List[Any]]]) -> None:
 158         self._timestamp()
 159         head = next(rows)
 160         assert head
 161         self._write(f'<table><thead><tr><th colspan="{len(head)}">{heading}</th></tr><tr>')
 162         for cell in head:
 163             self._write(f'<th>{cell}</th>')
 164         self._write('</tr></thead><tbody>')
 165         for row in rows:
 166             if row is not None:
 167                 self._write('<tr>')
 168                 for cell in row:
 169                     self._write(f'<td>{cell}</td>')
 170                 self._write('</tr>')
 171         self._write('</tbody></table>')
 172
 173     def result_dump(self, heading: str, results: Iterator[Tuple[Any, Any]]) -> None:
 174         """ Print a list of search results generated by the generator function.
 175         """
 176         self._timestamp()
 177
 178         def format_osm(osm_object: Optional[Tuple[str, int]]) -> str:
 179             if not osm_object:
 180                 return '-'
 181
 182             t, i = osm_object
 183             if t == 'N':
 184                 fullt = 'node'
 185             elif t == 'W':
 186                 fullt = 'way'
 187             elif t == 'R':
 188                 fullt = 'relation'
 189             else:
 190                 return f'{t}{i}'
 191
 192             return f'<a href="https://www.openstreetmap.org/{fullt}/{i}">{t}{i}</a>'
 193
 194         self._write(f'<h5>{heading}</h5><p><dl>')
 195         total = 0
 196         for rank, res in results:
 197             self._write(f'<dt>[{rank:.3f}]</dt>  <dd>{res.source_table.name}(')
 198             self._write(f"{_debug_name(res)}, type=({','.join(res.category)}), ")
 199             self._write(f"rank={res.rank_address}, ")
 200             self._write(f"osm={format_osm(res.osm_object)}, ")
 201             self._write(f'cc={res.country_code}, ')
 202             self._write(f'importance={res.importance or float("nan"):.5f})</dd>')
 203             total += 1
 204         self._write(f'</dl><b>TOTAL:</b> {total}</p>')
 205
 206     def sql(self, conn: AsyncConnection, statement: 'sa.Executable',
 207             params: Union[Mapping[str, Any], Sequence[Mapping[str, Any]], None]) -> None:
 208         self._timestamp()
 209         sqlstr = self.format_sql(conn, statement, params)
 210         if CODE_HIGHLIGHT:
 211             sqlstr = highlight(sqlstr, PostgresLexer(),
 212                                HtmlFormatter(nowrap=True, lineseparator='<br />'))
 213             self._write(f'<div class="highlight"><code class="lang-sql">{sqlstr}</code></div>')
 214         else:
 215             self._write(f'<code class="lang-sql">{html.escape(sqlstr)}</code>')
 216
 217     def _python_var(self, var: Any) -> str:
 218         if CODE_HIGHLIGHT:
 219             fmt = highlight(str(var), PythonLexer(), HtmlFormatter(nowrap=True))
 220             return f'<div class="highlight"><code class="lang-python">{fmt}</code></div>'
 221
 222         return f'<code class="lang-python">{html.escape(str(var))}</code>'
 223
 224     def _write(self, text: str) -> None:
 225         """ Add the raw text to the debug output.
 226         """
 227         self.buffer.write(text)
 228
 229
 230 class TextLogger(BaseLogger):
 231     """ Logger creating output suitable for the console.
 232     """
 233     def __init__(self) -> None:
 234         self.buffer = io.StringIO()
 235
 236     def _timestamp(self) -> None:
 237         self._write(f'[{dt.datetime.now()}]\n')
 238
 239     def get_buffer(self) -> str:
 240         return self.buffer.getvalue()
 241
 242     def function(self, func: str, **kwargs: Any) -> None:
 243         self._write(f"#### Debug output for {func}()\n\nParameters:\n")
 244         for name, value in kwargs.items():
 245             self._write(f'  {name}: {self._python_var(value)}\n')
 246         self._write('\n')
 247
 248     def section(self, heading: str) -> None:
 249         self._timestamp()
 250         self._write(f"\n# {heading}\n\n")
 251
 252     def comment(self, text: str) -> None:
 253         self._write(f"{text}\n")
 254
 255     def var_dump(self, heading: str, var: Any) -> None:
 256         if callable(var):
 257             var = var()
 258
 259         self._write(f'{heading}:\n  {self._python_var(var)}\n\n')
 260
 261     def table_dump(self, heading: str, rows: Iterator[Optional[List[Any]]]) -> None:
 262         self._write(f'{heading}:\n')
 263         data = [list(map(self._python_var, row)) if row else None for row in rows]
 264         assert data[0] is not None
 265         num_cols = len(data[0])
 266
 267         maxlens = [max(len(d[i]) for d in data if d) for i in range(num_cols)]
 268         tablewidth = sum(maxlens) + 3 * num_cols + 1
 269         row_format = '| ' + ' | '.join(f'{{:<{ln}}}' for ln in maxlens) + ' |\n'
 270         self._write('-'*tablewidth + '\n')
 271         self._write(row_format.format(*data[0]))
 272         self._write('-'*tablewidth + '\n')
 273         for row in data[1:]:
 274             if row:
 275                 self._write(row_format.format(*row))
 276             else:
 277                 self._write('-'*tablewidth + '\n')
 278         if data[-1]:
 279             self._write('-'*tablewidth + '\n')
 280
 281     def result_dump(self, heading: str, results: Iterator[Tuple[Any, Any]]) -> None:
 282         self._timestamp()
 283         self._write(f'{heading}:\n')
 284         total = 0
 285         for rank, res in results:
 286             self._write(f'[{rank:.3f}]  {res.source_table.name}(')
 287             self._write(f"{_debug_name(res)}, type=({','.join(res.category)}), ")
 288             self._write(f"rank={res.rank_address}, ")
 289             self._write(f"osm={''.join(map(str, res.osm_object or []))}, ")
 290             self._write(f'cc={res.country_code}, ')
 291             self._write(f'importance={res.importance or -1:.5f})\n')
 292             total += 1
 293         self._write(f'TOTAL: {total}\n\n')
 294
 295     def sql(self, conn: AsyncConnection, statement: 'sa.Executable',
 296             params: Union[Mapping[str, Any], Sequence[Mapping[str, Any]], None]) -> None:
 297         self._timestamp()
 298         sqlstr = '\n| '.join(textwrap.wrap(self.format_sql(conn, statement, params), width=78))
 299         self._write(f"| {sqlstr}\n\n")
 300
 301     def _python_var(self, var: Any) -> str:
 302         return str(var)
 303
 304     def _write(self, text: str) -> None:
 305         self.buffer.write(text)
 306
 307
 308 logger: ContextVar[BaseLogger] = ContextVar('logger', default=BaseLogger())
 309
 310
 311 def set_log_output(fmt: str) -> None:
 312     """ Enable collecting debug information.
 313     """
 314     if fmt == 'html':
 315         logger.set(HTMLLogger())
 316     elif fmt == 'text':
 317         logger.set(TextLogger())
 318     else:
 319         logger.set(BaseLogger())
 320
 321
 322 def log() -> BaseLogger:
 323     """ Return the logger for the current context.
 324     """
 325     return logger.get()
 326
 327
 328 def get_and_disable() -> str:
 329     """ Return the current content of the debug buffer and disable logging.
 330     """
 331     buf = logger.get().get_buffer()
 332     logger.set(BaseLogger())
 333     return buf
 334
 335
 336 HTML_HEADER: str = """<!DOCTYPE html>
 337 <html>
 338 <head>
 339   <title>Nominatim - Debug</title>
 340   <style>
 341 """ + \
 342     (HtmlFormatter(nobackground=True).get_style_defs('.highlight')  # type: ignore[no-untyped-call]
 343      if CODE_HIGHLIGHT else '') + \
 344     """
 345     h2 { font-size: x-large }
 346
 347     dl {
 348       padding-left: 10pt;
 349       font-family: monospace
 350     }
 351
 352     dt {
 353       float: left;
 354       font-weight: bold;
 355       margin-right: 0.5em
 356     }
 357
 358     dt::after { content: ": "; }
 359
 360     dd::after {
 361       clear: left;
 362       display: block
 363     }
 364
 365     .lang-sql {
 366       color: #555;
 367       font-size: small
 368     }
 369
 370     h5 {
 371         border: solid lightgrey 0.1pt;
 372         margin-bottom: 0;
 373         background-color: #f7f7f7
 374     }
 375
 376     h5 + .highlight {
 377         padding: 3pt;
 378         border: solid lightgrey 0.1pt
 379     }
 380
 381     table, th, tbody {
 382         border: thin solid;
 383         border-collapse: collapse;
 384     }
 385     td {
 386         border-right: thin solid;
 387         padding-left: 3pt;
 388         padding-right: 3pt;
 389     }
 390
 391     .timestamp {
 392         font-size: 0.8em;
 393         color: darkblue;
 394         width: calc(100% - 5pt);
 395         text-align: right;
 396         position: absolute;
 397         left: 0;
 398         margin-top: -5px;
 399     }
 400   </style>
 401 </head>
 402 <body>
 403 """
 404
 405 HTML_FOOTER: str = "</body></html>"