log.py 16.7 KB
Newer Older
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
# logging.py - logging and debugging for DHParser
#
# Copyright 2018  by Eckhart Arnold (arnold@badw.de)
#                 Bavarian Academy of Sciences an Humanities (badw.de)
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
#     http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or
# implied.  See the License for the specific language governing
# permissions and limitations under the License.
17

18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
"""
Module ``log`` contains logging and debugging support for the
parsing process.

For logging functionality, the global variable LOGGING is defined which
contains the name of a directory where log files shall be placed. By
setting its value to the empty string "" logging can be turned off.

To read the directory name function ``LOGS_DIR()`` should be called
rather than reading the variable LOGGING. ``LOGS_DIR()`` makes sure
the directory exists and raises an error if a file with the same name
already exists.

For debugging of the parsing process, the parsing history can be
logged and written to an html-File.

For ease of use module ``log`` defines a context-manager ``logging``
to which either ``False`` (turn off logging), a log directory name or
``True`` for the default logging directory is passed as argument.
The other components of DHParser check whether logging is on and
write log files in the the logging directory accordingly. Usually,
this will be concrete and abstract syntax trees as well as the full
and abreviated parsing history.

Example::

    from DHParser import compile_source, logging

    with logging("LOGS"):
        result, errors, ast = compile_source(source, preprocessor, grammar,
                                             transformer, compiler)
"""
50
51
52
53
54
55

import collections
import contextlib
import html
import os

56
from DHParser.error import Error
57
from DHParser.stringview import StringView
di68kap's avatar
di68kap committed
58
from DHParser.syntaxtree import Node
59
from DHParser.toolkit import is_filename, escape_control_characters, GLOBALS, typing
eckhart's avatar
eckhart committed
60
from typing import List, Tuple, Union
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89

__all__ = ('log_dir',
           'logging',
           'is_logging',
           'logfile_basename',
           'clear_logs',
           'HistoryRecord',
           'log_ST',
           'log_parsing_history')


#######################################################################
#
# logging context manager and logfile support
#
#######################################################################


def log_dir() -> str:
    """Creates a directory for log files (if it does not exist) and
    returns its path.

    WARNING: Any files in the log dir will eventually be overwritten.
    Don't use a directory name that could be the name of a directory
    for other purposes than logging.

    Returns:
        name of the logging directory
    """
90
    # the try-except clauses in the following are precautions for multithreading
91
    try:
92
        dirname = GLOBALS.LOGGING  # raises a name error if LOGGING is not defined
93
        if not dirname:
94
95
96
97
            raise AttributeError  # raise a name error if LOGGING evaluates to False
    except AttributeError:
        raise AttributeError("No access to log directory before logging has been "
                             "turned on within the same thread/process.")
98
99
100
101
102
103
104
105
106
107
    if os.path.exists(dirname) and not os.path.isdir(dirname):
        raise IOError('"' + dirname + '" cannot be used as log directory, '
                                      'because it is not a directory!')
    else:
        try:
            os.mkdir(dirname)
        except FileExistsError:
            pass
    info_file_name = os.path.join(dirname, 'info.txt')
    if not os.path.exists(info_file_name):
Eckhart Arnold's avatar
Eckhart Arnold committed
108
        with open(info_file_name, 'w', encoding="utf-8") as f:
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
            f.write("This directory has been created by DHParser to store log files from\n"
                    "parsing. ANY FILE IN THIS DIRECTORY CAN BE OVERWRITTEN! Therefore,\n"
                    "do not place any files here and do not bother editing files in this\n"
                    "directory as any changes will get lost.\n")
    return dirname


@contextlib.contextmanager
def logging(dirname="LOGS"):
    """Context manager. Log files within this context will be stored in
    directory ``dirname``. Logging is turned off if name is empty.

    Args:
        dirname: the name for the log directory or the empty string to
            turn logging of
    """
    if dirname and not isinstance(dirname, str):
        dirname = "LOGS"  # be fail tolerant here...
    try:
128
        save = GLOBALS.LOGGING
129
    except AttributeError:
130
        save = ""
131
    GLOBALS.LOGGING = dirname or ""
132
    yield
133
    GLOBALS.LOGGING = save
134
135
136
137
138


def is_logging() -> bool:
    """-> True, if logging is turned on."""
    try:
139
        return bool(GLOBALS.LOGGING)
140
    except AttributeError:
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
        return False


def logfile_basename(filename_or_text, function_or_class_or_instance) -> str:
    """Generates a reasonable logfile-name (without extension) based on
    the given information.
    """
    if is_filename(filename_or_text):
        return os.path.basename(os.path.splitext(filename_or_text)[0])
    else:
        try:
            name = function_or_class_or_instance.__qualname.__
        except AttributeError:
            name = function_or_class_or_instance.__class__.__name__
        i = name.find('.')
        return name[:i] + '_out' if i >= 0 else name


def clear_logs(logfile_types=frozenset(['.cst', '.ast', '.log'])):
    """Removes all logs from the log-directory and removes the
    log-directory if it is empty.
    """
    log_dirname = log_dir()
    files = os.listdir(log_dirname)
    only_log_files = True
    for file in files:
        path = os.path.join(log_dirname, file)
        if os.path.splitext(file)[1] in logfile_types or file == 'info.txt':
            os.remove(path)
        else:
            only_log_files = False
    if only_log_files:
        os.rmdir(log_dirname)


#######################################################################
#
# parsing history
#
#######################################################################


class HistoryRecord:
    """
    Stores debugging information about one completed step in the
    parsing history.

    A parsing step is "completed" when the last one of a nested
    sequence of parser-calls returns. The call stack including
    the last parser call will be frozen in the ``HistoryRecord``-
    object. In addition a reference to the generated leaf node
    (if any) will be stored and the result status of the last
    parser call, which ist either MATCH, FAIL (i.e. no match)
    or ERROR.
    """
196
    __slots__ = ('call_stack', 'node', 'text', 'line_col', 'errors')
197
198
199
200
201
202

    MATCH = "MATCH"
    ERROR = "ERROR"
    FAIL = "FAIL"
    Snapshot = collections.namedtuple('Snapshot', ['line', 'column', 'stack', 'status', 'text'])

203
204
205
    COLGROUP = '<colgroup>\n<col style="width:2%"/><col style="width:2%"/><col ' \
               'style="width:75%"/><col style="width:6%"/><col style="width:15%"/>\n</colgroup>'
    HEADINGS = ('<tr><th>L</th><th>C</th><th>parser call sequence</th>'
eckhart's avatar
eckhart committed
206
207
208
                '<th>success</th><th>text matched or failed</th></tr>')
    HTML_LEAD_IN = (
        '<!DOCTYPE html>\n'
209
        '<html>\n<head>\n<meta charset="utf-8"/>\n<style>\n'
210
        'td,th {font-family:monospace; '
eckhart's avatar
eckhart committed
211
        'border-right: thin solid grey; border-bottom: thin solid grey}\n'
eckhart's avatar
eckhart committed
212
        'td.line, td.column {color:darkgrey}\n'  # 'td.stack {}\n'
213
214
215
216
217
218
219
220
        'td.status {font-weight:bold}\n'
        'td.text {color:darkblue}\n'
        'table {border-spacing: 0px; border: thin solid darkgrey; width:100%}\n'
        'span {color:grey;}\nspan.match {color:darkgreen}\n'
        'span.fail {color:darkgrey}\nspan.error {color:red}\n'
        'span.matchstack {font-weight:bold;color:darkred}'
        '\n</style>\n</head>\n<body>\n')
    HTML_LEAD_OUT = '\n</body>\n</html>\n'
221

222
223
224
    def __init__(self, call_stack: List[str],
                 node: Node,
                 text: StringView,
225
226
                 line_col: Tuple[int, int],
                 errors: List[Error] = []) -> None:
227
        # copy call stack, dropping uninformative Forward-Parsers
228
        self.call_stack = [tn for tn in call_stack if tn != ":Forward"]  # type: List[str]
229
230
        self.node = node                # type: Node
        self.text = text                # type: StringView
231
        self.line_col = line_col        # type: Tuple[int, int]
232
        self.errors = errors            # type: List[Error]
233
234
235
236

    def __str__(self):
        return '%4i, %2i:  %s;  %s;  "%s"' % self.as_tuple()

eckhart's avatar
eckhart committed
237
    def as_tuple(self) -> 'Snapshot':
238
239
240
241
242
        """
        Returns history record formatted as a snapshot tuple.
        """
        return self.Snapshot(self.line_col[0], self.line_col[1],
                             self.stack, self.status, self.excerpt)
243

244
245
246
247
248
249
250
251
252
253
254
    def as_csv_line(self) -> str:
        """
        Returns history record formatted as a csv table row.
        """
        return '"{}", "{}", "{}", "{}", "{}"'.format(*self.as_tuple())

    def as_html_tr(self) -> str:
        """
        Returns history record formatted as an html table row.
        """
        stack = html.escape(self.stack).replace(
255
            '-&gt;', '<span>&shy;-&gt;</span>')
256
257
258
259
260
        status = html.escape(self.status)
        excerpt = html.escape(self.excerpt)
        if status == self.MATCH:
            status = '<span class="match">' + status + '</span>'
            i = stack.rfind('-&gt;')
eckhart's avatar
eckhart committed
261
            chr = stack[i + 12:i + 13]
262
263
            while not chr.isidentifier() and i >= 0:
                i = stack.rfind('-&gt;', 0, i)
eckhart's avatar
eckhart committed
264
                chr = stack[i + 12:i + 13]
265
266
267
268
269
270
271
            if i >= 0:
                i += 12
                k = stack.find('<', i)
                if k < 0:
                    stack = stack[:i] + '<span class="matchstack">' + stack[i:]
                else:
                    stack = stack[:i] + '<span class="matchstack">' + stack[i:k] \
272
                        + '</span>' + stack[k:]
273
274
275
276
277
278
279
280
281
282
283
        elif status == self.FAIL:
            status = '<span class="fail">' + status + '</span>'
        else:
            stack += '<br/>\n' + status
            status = '<span class="error">ERROR</span>'
        tpl = self.Snapshot(str(self.line_col[0]), str(self.line_col[1]), stack, status, excerpt)
        # return ''.join(['<tr>'] + [('<td>%s</td>' % item) for item in tpl] + ['</tr>'])
        return ''.join(['<tr>'] + [('<td class="%s">%s</td>' % (cls, item))
                                   for cls, item in zip(tpl._fields, tpl)] + ['</tr>'])

    def err_msg(self) -> str:
284
        return self.ERROR + ": " + "; ".join(str(e) for e in (self.errors))
285
286
287

    @property
    def stack(self) -> str:
288
        return "->".join(self.call_stack)
289
290
291
292

    @property
    def status(self) -> str:
        return self.FAIL if self.node is None else \
293
            ('"%s"' % self.err_msg()) if self.errors else self.MATCH
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342

    @property
    def excerpt(self):
        length = len(self.node) if self.node else len(self.text)
        excerpt = str(self.node)[:min(length, 20)] if self.node else str(self.text[:20])
        excerpt = escape_control_characters(excerpt)
        if length > 20:
            excerpt += '...'
        return excerpt

    # @property
    # def extent(self) -> slice:
    #     return (slice(-self.remaining - len(self.node), -self.remaining) if self.node
    #             else slice(-self.remaining, None))

    @property
    def remaining(self) -> int:
        return len(self.text) - (len(self.node) if self.node else 0)

    @staticmethod
    def last_match(history: List['HistoryRecord']) -> Union['HistoryRecord', None]:
        """
        Returns the last match from the parsing-history.
        Args:
            history:  the parsing-history as a list of HistoryRecord objects

        Returns:
            the history record of the last match or none if either history is
            empty or no parser could match
        """
        for record in reversed(history):
            if record.status == HistoryRecord.MATCH:
                return record
        return None

    @staticmethod
    def most_advanced_match(history: List['HistoryRecord']) -> Union['HistoryRecord', None]:
        """
        Returns the closest-to-the-end-match from the parsing-history.
        Args:
            history:  the parsing-history as a list of HistoryRecord objects

        Returns:
            the history record of the closest-to-the-end-match or none if either history is
            empty or no parser could match
        """
        remaining = -1
        result = None
        for record in history:
eckhart's avatar
eckhart committed
343
344
            if (record.status == HistoryRecord.MATCH
                    and (record.remaining < remaining or remaining < 0)):
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
                result = record
                remaining = record.remaining
        return result


#######################################################################
#
#  context specific log functions, i.e. logging of syntax trees,
#  grammar history and the like
#
#######################################################################


def log_ST(syntax_tree, log_file_name):
    """
    Writes an S-expression-representation of the `syntax_tree` to a file,
    if logging is turned on.
    """
    if is_logging():
        path = os.path.join(log_dir(), log_file_name)
        if os.path.exists(path):
            print('WARNING: Log-file "%s" already exists and will be overwritten!' % path)
        with open(path, "w", encoding="utf-8") as f:
            f.write(syntax_tree.as_sxpr())


di68kap's avatar
di68kap committed
371
LOG_SIZE_THRESHOLD = 10000    # maximum number of history records to log
372
373
374
LOG_TAIL_THRESHOLD = 500      # maximum number of history recors for "tail log"


eckhart's avatar
eckhart committed
375
def log_parsing_history(grammar, log_file_name: str = '', html: bool = True) -> None:
376
    """
377
    Writes a log of the parsing history of the most recently parsed document.
378
379
380
381
382
383
384
385
386
387

    Parameters:
        grammar (Grammar):  The Grammar object from which the parsing history
            shall be logged.
        log_file_name (str):  The (base-)name of the log file to be written.
            If no name is given (default), then the class name of the grammar
            object will be used.
        html (bool):  If true (default), the log will be output as html-Table,
            otherwise as plain test. (Browsers might take a few seconds or
            minutes to display the table for long histories.)
388
389
390
391
392
393
394
395
396
397
    """
    def write_log(history, log_name):
        htm = '.html' if html else ''
        path = os.path.join(log_dir(), log_name + "_parser.log" + htm)
        if os.path.exists(path):
            os.remove(path)
            print('WARNING: Log-file "%s" already existed and was deleted.' % path)
        if history:
            with open(path, "w", encoding="utf-8") as f:
                if html:
398
                    f.write(HistoryRecord.HTML_LEAD_IN + '\n')
399
                    f.write("\n".join(history))
400
                    f.write('\n</table>\n' + HistoryRecord.HTML_LEAD_OUT)
401
402
403
404
405
406
407
408
                else:
                    f.write("\n".join(history))

    def append_line(log, line):
        """Appends a line to a list of HTML table rows. Starts a new
        table every 100 rows to allow browser to speed up rendering.
        Does this really work...?"""
        log.append(line)
409
410
        if html and len(log) % 50 == 0:
            log.append('\n'.join(['</table>\n<table>', HistoryRecord.COLGROUP]))
411
412
413

    if not is_logging():
        raise AssertionError("Cannot log history when logging is turned off!")
eckhart's avatar
eckhart committed
414

415
416
417
418
419
    if not log_file_name:
        name = grammar.__class__.__name__
        log_file_name = name[:-7] if name.lower().endswith('grammar') else name
    elif log_file_name.lower().endswith('.log'):
        log_file_name = log_file_name[:-4]
420
421
422
423

    full_history = ['<h1>Full parsing history of "%s"</h1>' % log_file_name]  # type: List[str]

    if len(grammar.history__) > LOG_SIZE_THRESHOLD:
eckhart's avatar
eckhart committed
424
425
426
        warning = ('Sorry, man, %iK history records is just too many! '
                   'Only looking at the last %iK records.'
                   % (len(grammar.history__) // 1000, LOG_SIZE_THRESHOLD // 1000))
427
428
429
430
431
432
433
        html_warning = '<p><strong>' + warning + '</strong></p>'
        full_history.append(html_warning)

    lead_in = '\n'. join(['<table>', HistoryRecord.COLGROUP, HistoryRecord.HEADINGS])
    full_history.append(lead_in)

    for record in grammar.history__[-LOG_SIZE_THRESHOLD:]:
434
435
        line = record.as_html_tr() if html else str(record)
        append_line(full_history, line)
eckhart's avatar
eckhart committed
436

437
    write_log(full_history, log_file_name + '_full')
438
439
440
    if len(full_history) > LOG_TAIL_THRESHOLD + 10:
        heading = '<h1>Last 500 records of parsing history of "%s"</h1>' % log_file_name + lead_in
        write_log([heading] + full_history[-LOG_TAIL_THRESHOLD:], log_file_name + '_full.tail')