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