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