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