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