log.py 17.8 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

import collections
import contextlib
import html
import os
55
from typing import List, Tuple, Union, Optional
56

57
from DHParser.error import Error
58
from DHParser.stringview import StringView
59
from DHParser.syntaxtree import Node, ZOMBIE_TAG
60
from DHParser.toolkit import is_filename, escape_control_characters, GLOBALS
61 62 63 64

__all__ = ('log_dir',
           'logging',
           'is_logging',
65
           'create_log',
66
           'append_log',
67 68 69 70 71 72 73 74 75 76 77 78 79
           'clear_logs',
           'HistoryRecord',
           'log_ST',
           'log_parsing_history')


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


80
def log_dir() -> Union[str, bool]:
81 82 83 84 85 86 87
    """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.

88 89 90 91 92 93
    ATTENTION: The log-dir is sotred thread locally, which means the log-dir
    as well as the information whether logging is turned on or off will not
    automatically be transferred to any subprocesses. This needs to be done
    explicitly. (See `testing.grammar_suite()` for an example, how this can
    be done.

94
    Returns:
95 96
        name of the logging directory (str) or False (bool) if logging has
        not been switched on with the logging-contextmanager (see below), yet.
97
    """
98
    # the try-except clauses in the following are precautions for multithreading
99
    try:
100
        dirname = GLOBALS.LOGGING  # raises a name error if LOGGING is not defined
101
        if not dirname:
102 103
            raise AttributeError  # raise a name error if LOGGING evaluates to False
    except AttributeError:
104 105 106
        return False
        # raise AttributeError("No access to log directory before logging has been "
        #                      "turned on within the same thread/process.")
107 108 109 110 111 112 113 114 115 116
    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
117
        with open(info_file_name, 'w', encoding="utf-8") as f:
118 119 120 121 122 123 124
            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


125
#TODO: Remove this context manager, not really useful...s
126 127 128 129 130 131 132 133 134 135 136 137
@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:
138
        save = GLOBALS.LOGGING
139
    except AttributeError:
140
        save = ""
141
    GLOBALS.LOGGING = dirname or ""
142 143
    # if dirname and not os.path.exists(dirname):
    #     os.mkdir(dirname)
144
    yield
145
    GLOBALS.LOGGING = save
146 147 148 149 150


def is_logging() -> bool:
    """-> True, if logging is turned on."""
    try:
151
        return bool(GLOBALS.LOGGING)
152
    except AttributeError:
153 154 155
        return False


156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172
def create_log(log_name: str) -> str:
    """
    Creates a new log file in the log directory. If a file with
    the same name already exists, it will be overwritten.
    :param log_name: The file name of the log file to be created
    :return: the file name of the log file.
    """
    ldir = log_dir()
    if ldir:
        with open(os.path.join(ldir, log_name), 'w') as f:
            f.write('LOG-FILE: ' + log_name + '\n\n')
    return log_name


def append_log(log_name: str, *strings) -> None:
    """
    Appends one or more strings to the log-file with the name 'log_name'.
173
    """
174 175 176
    ldir = log_dir()
    if ldir:
        with open(os.path.join(ldir, log_name), 'a') as f:
177 178
            for text in strings:
                f.write(text)
179 180 181


def clear_logs(logfile_types=frozenset(['.cst', '.ast', '.log'])):
182 183
    """
    Removes all logs from the log-directory and removes the
184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218
    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.
    """
219
    __slots__ = ('call_stack', 'node', 'text', 'line_col', 'errors')
220 221 222 223 224 225

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

226 227 228
    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
229 230 231
                '<th>success</th><th>text matched or failed</th></tr>')
    HTML_LEAD_IN = (
        '<!DOCTYPE html>\n'
232
        '<html>\n<head>\n<meta charset="utf-8"/>\n<style>\n'
233
        'td,th {font-family:monospace; '
eckhart's avatar
eckhart committed
234
        'border-right: thin solid grey; border-bottom: thin solid grey}\n'
eckhart's avatar
eckhart committed
235
        'td.line, td.column {color:darkgrey}\n'  # 'td.stack {}\n'
236 237 238 239 240 241 242 243
        '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'
244

245
    def __init__(self, call_stack: List[str],
246
                 node: Optional[Node],
247
                 text: StringView,
248 249
                 line_col: Tuple[int, int],
                 errors: List[Error] = []) -> None:
250
        # copy call stack, dropping uninformative Forward-Parsers
251
        self.call_stack = [tn for tn in call_stack if tn != ":Forward"]  # type: List[str]
252
        self.node = node                # type: Optional[Node]
253
        self.text = text                # type: StringView
254
        self.line_col = line_col        # type: Tuple[int, int]
255
        self.errors = errors            # type: List[Error]
256 257 258 259

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

260 261 262 263 264
    def __repr__(self):
        return 'HistoryRecord(%s, %s, %s, %s, %s)' % \
               (repr(self.call_stack), repr(self.node), repr(self.text),
                repr(self.line_col), repr(self.errors))

eckhart's avatar
eckhart committed
265
    def as_tuple(self) -> 'Snapshot':
266 267 268 269 270
        """
        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)
271

272 273 274 275 276 277 278 279 280 281 282
    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(
283
            '-&gt;', '<span>&shy;-&gt;</span>')
284 285 286 287 288
        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
289
            chr = stack[i + 12:i + 13]
290 291
            while not chr.isidentifier() and i >= 0:
                i = stack.rfind('-&gt;', 0, i)
eckhart's avatar
eckhart committed
292
                chr = stack[i + 12:i + 13]
293 294 295 296 297 298 299
            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] \
300
                        + '</span>' + stack[k:]
301 302 303 304 305 306 307 308 309 310 311
        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:
312
        return self.ERROR + ": " + "; ".join(str(e) for e in (self.errors))
313 314 315

    @property
    def stack(self) -> str:
316
        return "->".join(self.call_stack)
317 318 319

    @property
    def status(self) -> str:
320
        return self.FAIL if self.node is None or self.node.tag_name == ZOMBIE_TAG else \
321
            ('"%s"' % self.err_msg()) if self.errors else self.MATCH
322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337 338 339 340 341 342 343 344 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

    @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
371 372
            if (record.status == HistoryRecord.MATCH
                    and (record.remaining < remaining or remaining < 0)):
373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392
                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)
393 394
        # if os.path.exists(path):
        #     print('WARNING: Log-file "%s" already exists and will be overwritten!' % path)
395 396 397 398
        with open(path, "w", encoding="utf-8") as f:
            f.write(syntax_tree.as_sxpr())


di68kap's avatar
di68kap committed
399
LOG_SIZE_THRESHOLD = 10000    # maximum number of history records to log
400 401 402
LOG_TAIL_THRESHOLD = 500      # maximum number of history recors for "tail log"


eckhart's avatar
eckhart committed
403
def log_parsing_history(grammar, log_file_name: str = '', html: bool = True) -> None:
404
    """
405
    Writes a log of the parsing history of the most recently parsed document.
406 407 408 409 410 411 412 413 414 415

    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.)
416 417 418 419 420 421
    """
    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)
422
            # print('WARNING: Log-file "%s" already existed and was deleted.' % path)
423 424 425
        if history:
            with open(path, "w", encoding="utf-8") as f:
                if html:
426
                    f.write(HistoryRecord.HTML_LEAD_IN + '\n')
427
                    f.write("\n".join(history))
428
                    f.write('\n</table>\n' + HistoryRecord.HTML_LEAD_OUT)
429 430 431 432 433 434 435 436
                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)
437 438
        if html and len(log) % 50 == 0:
            log.append('\n'.join(['</table>\n<table>', HistoryRecord.COLGROUP]))
439 440 441

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

443 444 445 446 447
    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]
448 449 450 451

    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
452 453 454
        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))
455 456 457 458 459 460 461
        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:]:
462 463
        line = record.as_html_tr() if html else str(record)
        append_line(full_history, line)
eckhart's avatar
eckhart committed
464

465
    write_log(full_history, log_file_name + '_full')
466 467 468
    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')