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