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