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