1from __future__ import print_function, division, absolute_import
2from fontTools.misc.py23 import *
3from fontTools.misc.loggingTools import (
4    LevelFormatter,
5    Timer,
6    configLogger,
7    ChannelsFilter,
8    LogMixin,
9    StderrHandler,
10    LastResortLogger,
11    _resetExistingLoggers,
12)
13import logging
14import textwrap
15import time
16import re
17import sys
18import pytest
19
20
21def logger_name_generator():
22    basename = "fontTools.test#"
23    num = 1
24    while True:
25        yield basename+str(num)
26        num += 1
27
28unique_logger_name = logger_name_generator()
29
30
31@pytest.fixture
32def logger():
33    log = logging.getLogger(next(unique_logger_name))
34    configLogger(logger=log, level="DEBUG", stream=StringIO())
35    return log
36
37
38def test_LevelFormatter():
39    stream = StringIO()
40    handler = logging.StreamHandler(stream)
41    formatter = LevelFormatter(
42        fmt={
43            '*':     '[%(levelname)s] %(message)s',
44            'DEBUG': '%(name)s [%(levelname)s] %(message)s',
45            'INFO':  '%(message)s',
46        })
47    handler.setFormatter(formatter)
48    name = next(unique_logger_name)
49    log = logging.getLogger(name)
50    log.setLevel(logging.DEBUG)
51    log.addHandler(handler)
52
53    log.debug("this uses a custom format string")
54    log.info("this also uses a custom format string")
55    log.warning("this one uses the default format string")
56
57    assert stream.getvalue() == textwrap.dedent("""\
58        %s [DEBUG] this uses a custom format string
59        this also uses a custom format string
60        [WARNING] this one uses the default format string
61        """ % name)
62
63
64class TimerTest(object):
65
66    def test_split(self):
67        timer = Timer()
68        time.sleep(0.01)
69        fist_lap =  timer.split()
70        assert timer.elapsed == fist_lap
71        time.sleep(0.1)
72        second_lap = timer.split()
73        assert second_lap > fist_lap
74        assert timer.elapsed == second_lap
75
76    def test_time(self):
77        timer = Timer()
78        time.sleep(0.01)
79        overall_time = timer.time()
80        assert overall_time > 0
81
82    def test_context_manager(self):
83        with Timer() as t:
84            time.sleep(0.01)
85        assert t.elapsed > 0
86
87    def test_using_logger(self, logger):
88        with Timer(logger, 'do something'):
89            time.sleep(0.01)
90
91        assert re.match(
92            "Took [0-9]\.[0-9]{3}s to do something",
93            logger.handlers[0].stream.getvalue())
94
95    def test_using_logger_calling_instance(self, logger):
96        timer = Timer(logger)
97        with timer():
98            time.sleep(0.01)
99
100        assert re.match(
101            "elapsed time: [0-9]\.[0-9]{3}s",
102            logger.handlers[0].stream.getvalue())
103
104        # do it again but with custom level
105        with timer('redo it', level=logging.WARNING):
106            time.sleep(0.02)
107
108        assert re.search(
109            "WARNING: Took [0-9]\.[0-9]{3}s to redo it",
110            logger.handlers[0].stream.getvalue())
111
112    def test_function_decorator(self, logger):
113        timer = Timer(logger)
114
115        @timer()
116        def test1():
117            time.sleep(0.01)
118        @timer('run test 2', level=logging.INFO)
119        def test2():
120            time.sleep(0.02)
121
122        test1()
123
124        assert re.match(
125            r"Took [0-9]\.[0-9]{3}s to run 'test1'",
126            logger.handlers[0].stream.getvalue())
127
128        test2()
129
130        assert re.search(
131            r"Took [0-9]\.[0-9]{3}s to run test 2",
132            logger.handlers[0].stream.getvalue())
133
134
135def test_ChannelsFilter(logger):
136    n = logger.name
137    filtr = ChannelsFilter(n+".A.B", n+".C.D")
138    handler = logger.handlers[0]
139    handler.addFilter(filtr)
140    stream = handler.stream
141
142    logging.getLogger(n+".A.B").debug('this record passes through')
143    assert 'this record passes through' in stream.getvalue()
144
145    logging.getLogger(n+'.A.B.C').debug('records from children also pass')
146    assert 'records from children also pass' in stream.getvalue()
147
148    logging.getLogger(n+'.C.D').debug('this one as well')
149    assert 'this one as well' in stream.getvalue()
150
151    logging.getLogger(n+'.A.B.').debug('also this one')
152    assert 'also this one' in stream.getvalue()
153
154    before = stream.getvalue()
155    logging.getLogger(n+'.A.F').debug('but this one does not!')
156    assert before == stream.getvalue()
157
158    logging.getLogger(n+'.C.DE').debug('neither this one!')
159    assert before == stream.getvalue()
160
161
162def test_LogMixin():
163
164    class Base(object):
165        pass
166
167    class A(LogMixin, Base):
168        pass
169
170    class B(A):
171        pass
172
173    a = A()
174    b = B()
175
176    assert hasattr(a, 'log')
177    assert hasattr(b, 'log')
178    assert isinstance(a.log, logging.Logger)
179    assert isinstance(b.log, logging.Logger)
180    assert a.log.name == "loggingTools_test.A"
181    assert b.log.name == "loggingTools_test.B"
182
183
184@pytest.mark.skipif(sys.version_info[:2] > (2, 7), reason="only for python2.7")
185@pytest.mark.parametrize(
186    "reset", [True, False], ids=["reset", "no-reset"]
187)
188def test_LastResortLogger(reset, capsys, caplog):
189    current = logging.getLoggerClass()
190    msg = "The quick brown fox jumps over the lazy dog"
191    try:
192        if reset:
193            _resetExistingLoggers()
194        else:
195            caplog.set_level(logging.ERROR, logger="myCustomLogger")
196        logging.lastResort = StderrHandler(logging.WARNING)
197        logging.setLoggerClass(LastResortLogger)
198        logger = logging.getLogger("myCustomLogger")
199        logger.error(msg)
200    finally:
201        del logging.lastResort
202        logging.setLoggerClass(current)
203
204    captured = capsys.readouterr()
205    if reset:
206        assert msg in captured.err
207        msg not in caplog.text
208    else:
209        msg in caplog.text
210        msg not in captured.err
211