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 get_buffer(self) -> str:
 239         return self.buffer.getvalue()
 240
 241
 242     def function(self, func: str, **kwargs: Any) -> None:
 243         self._write(f"#### Debug output for {func}()\n\nParameters:\n")
 244         for name, value in kwargs.items():
 245             self._write(f'  {name}: {self._python_var(value)}\n')
 246         self._write('\n')
 247
 248
 249     def section(self, heading: str) -> None:
 250         self._write(f"\n# {heading}\n\n")
 251
 252
 253     def comment(self, text: str) -> None:
 254         self._write(f"{text}\n")
 255
 256
 257     def var_dump(self, heading: str, var: Any) -> None:
 258         if callable(var):
 259             var = var()
 260
 261         self._write(f'{heading}:\n  {self._python_var(var)}\n\n')
 262
 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'{{:<{l}}}' for l 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
 285     def result_dump(self, heading: str, results: Iterator[Tuple[Any, Any]]) -> None:
 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
 299     def sql(self, conn: AsyncConnection, statement: 'sa.Executable',
 300             params: Union[Mapping[str, Any], Sequence[Mapping[str, Any]], None]) -> None:
 301         sqlstr = '\n| '.join(textwrap.wrap(self.format_sql(conn, statement, params), width=78))
 302         self._write(f"| {sqlstr}\n\n")
 303
 304
 305     def _python_var(self, var: Any) -> str:
 306         return str(var)
 307
 308
 309     def _write(self, text: str) -> None:
 310         self.buffer.write(text)
 311
 312
 313 logger: ContextVar[BaseLogger] = ContextVar('logger', default=BaseLogger())
 314
 315
 316 def set_log_output(fmt: str) -> None:
 317     """ Enable collecting debug information.
 318     """
 319     if fmt == 'html':
 320         logger.set(HTMLLogger())
 321     elif fmt == 'text':
 322         logger.set(TextLogger())
 323     else:
 324         logger.set(BaseLogger())
 325
 326
 327 def log() -> BaseLogger:
 328     """ Return the logger for the current context.
 329     """
 330     return logger.get()
 331
 332
 333 def get_and_disable() -> str:
 334     """ Return the current content of the debug buffer and disable logging.
 335     """
 336     buf = logger.get().get_buffer()
 337     logger.set(BaseLogger())
 338     return buf
 339
 340
 341 HTML_HEADER: str = """<!DOCTYPE html>
 342 <html>
 343 <head>
 344   <title>Nominatim - Debug</title>
 345   <style>
 346 """ + \
 347 (HtmlFormatter(nobackground=True).get_style_defs('.highlight') if CODE_HIGHLIGHT else '') +\
 348 """
 349     h2 { font-size: x-large }
 350
 351     dl {
 352       padding-left: 10pt;
 353       font-family: monospace
 354     }
 355
 356     dt {
 357       float: left;
 358       font-weight: bold;
 359       margin-right: 0.5em
 360     }
 361
 362     dt::after { content: ": "; }
 363
 364     dd::after {
 365       clear: left;
 366       display: block
 367     }
 368
 369     .lang-sql {
 370       color: #555;
 371       font-size: small
 372     }
 373
 374     h5 {
 375         border: solid lightgrey 0.1pt;
 376         margin-bottom: 0;
 377         background-color: #f7f7f7
 378     }
 379
 380     h5 + .highlight {
 381         padding: 3pt;
 382         border: solid lightgrey 0.1pt
 383     }
 384
 385     table, th, tbody {
 386         border: thin solid;
 387         border-collapse: collapse;
 388     }
 389     td {
 390         border-right: thin solid;
 391         padding-left: 3pt;
 392         padding-right: 3pt;
 393     }
 394
 395     .timestamp {
 396         font-size: 0.8em;
 397         color: darkblue;
 398         width: calc(100% - 5pt);
 399         text-align: right;
 400         position: absolute;
 401         left: 0;
 402         margin-top: -5px;
 403     }
 404   </style>
 405 </head>
 406 <body>
 407 """
 408
 409 HTML_FOOTER: str = "</body></html>"