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