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) 2024 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             # Fixes an odd issue with Python 3.7 where percentages are not
 110             # quoted correctly.
 111             sqlstr = re.sub(r'%(?!\()', '%%', sqlstr)
 112             sqlstr = re.sub(r'__\[POSTCOMPILE_([^]]*)\]', r'%(\1)s', sqlstr)
 113             return sqlstr % params
 114
 115         assert conn.dialect.name == 'sqlite'
 116
 117         # params in positional order
 118         pparams = (repr(params.get(name, None)) for name in compiled.positiontup)  # type: ignore
 119
 120         sqlstr = re.sub(r'__\[POSTCOMPILE_([^]]*)\]', '?', sqlstr)
 121         sqlstr = re.sub(r"\?", lambda m: next(pparams), sqlstr)
 122
 123         return sqlstr
 124
 125
 126 class HTMLLogger(BaseLogger):
 127     """ Logger that formats messages in HTML.
 128     """
 129     def __init__(self) -> None:
 130         self.buffer = io.StringIO()
 131
 132     def _timestamp(self) -> None:
 133         self._write(f'<p class="timestamp">[{dt.datetime.now()}]</p>')
 134
 135     def get_buffer(self) -> str:
 136         return HTML_HEADER + self.buffer.getvalue() + HTML_FOOTER
 137
 138     def function(self, func: str, **kwargs: Any) -> None:
 139         self._timestamp()
 140         self._write(f"<h1>Debug output for {func}()</h1>\n<p>Parameters:<dl>")
 141         for name, value in kwargs.items():
 142             self._write(f'<dt>{name}</dt><dd>{self._python_var(value)}</dd>')
 143         self._write('</dl></p>')
 144
 145     def section(self, heading: str) -> None:
 146         self._timestamp()
 147         self._write(f"<h2>{heading}</h2>")
 148
 149     def comment(self, text: str) -> None:
 150         self._timestamp()
 151         self._write(f"<p>{text}</p>")
 152
 153     def var_dump(self, heading: str, var: Any) -> None:
 154         self._timestamp()
 155         if callable(var):
 156             var = var()
 157
 158         self._write(f'<h5>{heading}</h5>{self._python_var(var)}')
 159
 160     def table_dump(self, heading: str, rows: Iterator[Optional[List[Any]]]) -> None:
 161         self._timestamp()
 162         head = next(rows)
 163         assert head
 164         self._write(f'<table><thead><tr><th colspan="{len(head)}">{heading}</th></tr><tr>')
 165         for cell in head:
 166             self._write(f'<th>{cell}</th>')
 167         self._write('</tr></thead><tbody>')
 168         for row in rows:
 169             if row is not None:
 170                 self._write('<tr>')
 171                 for cell in row:
 172                     self._write(f'<td>{cell}</td>')
 173                 self._write('</tr>')
 174         self._write('</tbody></table>')
 175
 176     def result_dump(self, heading: str, results: Iterator[Tuple[Any, Any]]) -> None:
 177         """ Print a list of search results generated by the generator function.
 178         """
 179         self._timestamp()
 180
 181         def format_osm(osm_object: Optional[Tuple[str, int]]) -> str:
 182             if not osm_object:
 183                 return '-'
 184
 185             t, i = osm_object
 186             if t == 'N':
 187                 fullt = 'node'
 188             elif t == 'W':
 189                 fullt = 'way'
 190             elif t == 'R':
 191                 fullt = 'relation'
 192             else:
 193                 return f'{t}{i}'
 194
 195             return f'<a href="https://www.openstreetmap.org/{fullt}/{i}">{t}{i}</a>'
 196
 197         self._write(f'<h5>{heading}</h5><p><dl>')
 198         total = 0
 199         for rank, res in results:
 200             self._write(f'<dt>[{rank:.3f}]</dt>  <dd>{res.source_table.name}(')
 201             self._write(f"{_debug_name(res)}, type=({','.join(res.category)}), ")
 202             self._write(f"rank={res.rank_address}, ")
 203             self._write(f"osm={format_osm(res.osm_object)}, ")
 204             self._write(f'cc={res.country_code}, ')
 205             self._write(f'importance={res.importance or float("nan"):.5f})</dd>')
 206             total += 1
 207         self._write(f'</dl><b>TOTAL:</b> {total}</p>')
 208
 209     def sql(self, conn: AsyncConnection, statement: 'sa.Executable',
 210             params: Union[Mapping[str, Any], Sequence[Mapping[str, Any]], None]) -> None:
 211         self._timestamp()
 212         sqlstr = self.format_sql(conn, statement, params)
 213         if CODE_HIGHLIGHT:
 214             sqlstr = highlight(sqlstr, PostgresLexer(),
 215                                HtmlFormatter(nowrap=True, lineseparator='<br />'))
 216             self._write(f'<div class="highlight"><code class="lang-sql">{sqlstr}</code></div>')
 217         else:
 218             self._write(f'<code class="lang-sql">{html.escape(sqlstr)}</code>')
 219
 220     def _python_var(self, var: Any) -> str:
 221         if CODE_HIGHLIGHT:
 222             fmt = highlight(str(var), PythonLexer(), HtmlFormatter(nowrap=True))
 223             return f'<div class="highlight"><code class="lang-python">{fmt}</code></div>'
 224
 225         return f'<code class="lang-python">{html.escape(str(var))}</code>'
 226
 227     def _write(self, text: str) -> None:
 228         """ Add the raw text to the debug output.
 229         """
 230         self.buffer.write(text)
 231
 232
 233 class TextLogger(BaseLogger):
 234     """ Logger creating output suitable for the console.
 235     """
 236     def __init__(self) -> None:
 237         self.buffer = io.StringIO()
 238
 239     def _timestamp(self) -> None:
 240         self._write(f'[{dt.datetime.now()}]\n')
 241
 242     def get_buffer(self) -> str:
 243         return self.buffer.getvalue()
 244
 245     def function(self, func: str, **kwargs: Any) -> None:
 246         self._write(f"#### Debug output for {func}()\n\nParameters:\n")
 247         for name, value in kwargs.items():
 248             self._write(f'  {name}: {self._python_var(value)}\n')
 249         self._write('\n')
 250
 251     def section(self, heading: str) -> None:
 252         self._timestamp()
 253         self._write(f"\n# {heading}\n\n")
 254
 255     def comment(self, text: str) -> None:
 256         self._write(f"{text}\n")
 257
 258     def var_dump(self, heading: str, var: Any) -> None:
 259         if callable(var):
 260             var = var()
 261
 262         self._write(f'{heading}:\n  {self._python_var(var)}\n\n')
 263
 264     def table_dump(self, heading: str, rows: Iterator[Optional[List[Any]]]) -> None:
 265         self._write(f'{heading}:\n')
 266         data = [list(map(self._python_var, row)) if row else None for row in rows]
 267         assert data[0] is not None
 268         num_cols = len(data[0])
 269
 270         maxlens = [max(len(d[i]) for d in data if d) for i in range(num_cols)]
 271         tablewidth = sum(maxlens) + 3 * num_cols + 1
 272         row_format = '| ' + ' | '.join(f'{{:<{ln}}}' for ln in maxlens) + ' |\n'
 273         self._write('-'*tablewidth + '\n')
 274         self._write(row_format.format(*data[0]))
 275         self._write('-'*tablewidth + '\n')
 276         for row in data[1:]:
 277             if row:
 278                 self._write(row_format.format(*row))
 279             else:
 280                 self._write('-'*tablewidth + '\n')
 281         if data[-1]:
 282             self._write('-'*tablewidth + '\n')
 283
 284     def result_dump(self, heading: str, results: Iterator[Tuple[Any, Any]]) -> None:
 285         self._timestamp()
 286         self._write(f'{heading}:\n')
 287         total = 0
 288         for rank, res in results:
 289             self._write(f'[{rank:.3f}]  {res.source_table.name}(')
 290             self._write(f"{_debug_name(res)}, type=({','.join(res.category)}), ")
 291             self._write(f"rank={res.rank_address}, ")
 292             self._write(f"osm={''.join(map(str, res.osm_object or []))}, ")
 293             self._write(f'cc={res.country_code}, ')
 294             self._write(f'importance={res.importance or -1:.5f})\n')
 295             total += 1
 296         self._write(f'TOTAL: {total}\n\n')
 297
 298     def sql(self, conn: AsyncConnection, statement: 'sa.Executable',
 299             params: Union[Mapping[str, Any], Sequence[Mapping[str, Any]], None]) -> None:
 300         self._timestamp()
 301         sqlstr = '\n| '.join(textwrap.wrap(self.format_sql(conn, statement, params), width=78))
 302         self._write(f"| {sqlstr}\n\n")
 303
 304     def _python_var(self, var: Any) -> str:
 305         return str(var)
 306
 307     def _write(self, text: str) -> None:
 308         self.buffer.write(text)
 309
 310
 311 logger: ContextVar[BaseLogger] = ContextVar('logger', default=BaseLogger())
 312
 313
 314 def set_log_output(fmt: str) -> None:
 315     """ Enable collecting debug information.
 316     """
 317     if fmt == 'html':
 318         logger.set(HTMLLogger())
 319     elif fmt == 'text':
 320         logger.set(TextLogger())
 321     else:
 322         logger.set(BaseLogger())
 323
 324
 325 def log() -> BaseLogger:
 326     """ Return the logger for the current context.
 327     """
 328     return logger.get()
 329
 330
 331 def get_and_disable() -> str:
 332     """ Return the current content of the debug buffer and disable logging.
 333     """
 334     buf = logger.get().get_buffer()
 335     logger.set(BaseLogger())
 336     return buf
 337
 338
 339 HTML_HEADER: str = """<!DOCTYPE html>
 340 <html>
 341 <head>
 342   <title>Nominatim - Debug</title>
 343   <style>
 344 """ + \
 345     (HtmlFormatter(nobackground=True).get_style_defs('.highlight') if CODE_HIGHLIGHT else '') + \
 346     """
 347     h2 { font-size: x-large }
 348
 349     dl {
 350       padding-left: 10pt;
 351       font-family: monospace
 352     }
 353
 354     dt {
 355       float: left;
 356       font-weight: bold;
 357       margin-right: 0.5em
 358     }
 359
 360     dt::after { content: ": "; }
 361
 362     dd::after {
 363       clear: left;
 364       display: block
 365     }
 366
 367     .lang-sql {
 368       color: #555;
 369       font-size: small
 370     }
 371
 372     h5 {
 373         border: solid lightgrey 0.1pt;
 374         margin-bottom: 0;
 375         background-color: #f7f7f7
 376     }
 377
 378     h5 + .highlight {
 379         padding: 3pt;
 380         border: solid lightgrey 0.1pt
 381     }
 382
 383     table, th, tbody {
 384         border: thin solid;
 385         border-collapse: collapse;
 386     }
 387     td {
 388         border-right: thin solid;
 389         padding-left: 3pt;
 390         padding-right: 3pt;
 391     }
 392
 393     .timestamp {
 394         font-size: 0.8em;
 395         color: darkblue;
 396         width: calc(100% - 5pt);
 397         text-align: right;
 398         position: absolute;
 399         left: 0;
 400         margin-top: -5px;
 401     }
 402   </style>
 403 </head>
 404 <body>
 405 """
 406
 407 HTML_FOOTER: str = "</body></html>"