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