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