• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1from fontTools.misc.loggingTools import (
2    LevelFormatter,
3    Timer,
4    configLogger,
5    ChannelsFilter,
6    LogMixin,
7)
8from io import StringIO
9import logging
10import textwrap
11import time
12import re
13import pytest
14
15
16def logger_name_generator():
17    basename = "fontTools.test#"
18    num = 1
19    while True:
20        yield basename+str(num)
21        num += 1
22
23unique_logger_name = logger_name_generator()
24
25
26@pytest.fixture
27def logger():
28    log = logging.getLogger(next(unique_logger_name))
29    configLogger(logger=log, level="DEBUG", stream=StringIO())
30    return log
31
32
33def test_LevelFormatter():
34    stream = StringIO()
35    handler = logging.StreamHandler(stream)
36    formatter = LevelFormatter(
37        fmt={
38            '*':     '[%(levelname)s] %(message)s',
39            'DEBUG': '%(name)s [%(levelname)s] %(message)s',
40            'INFO':  '%(message)s',
41        })
42    handler.setFormatter(formatter)
43    name = next(unique_logger_name)
44    log = logging.getLogger(name)
45    log.setLevel(logging.DEBUG)
46    log.addHandler(handler)
47
48    log.debug("this uses a custom format string")
49    log.info("this also uses a custom format string")
50    log.warning("this one uses the default format string")
51
52    assert stream.getvalue() == textwrap.dedent("""\
53        %s [DEBUG] this uses a custom format string
54        this also uses a custom format string
55        [WARNING] this one uses the default format string
56        """ % name)
57
58
59class TimerTest(object):
60
61    def test_split(self):
62        timer = Timer()
63        time.sleep(0.01)
64        fist_lap =  timer.split()
65        assert timer.elapsed == fist_lap
66        time.sleep(0.1)
67        second_lap = timer.split()
68        assert second_lap > fist_lap
69        assert timer.elapsed == second_lap
70
71    def test_time(self):
72        timer = Timer()
73        time.sleep(0.01)
74        overall_time = timer.time()
75        assert overall_time > 0
76
77    def test_context_manager(self):
78        with Timer() as t:
79            time.sleep(0.01)
80        assert t.elapsed > 0
81
82    def test_using_logger(self, logger):
83        with Timer(logger, 'do something'):
84            time.sleep(0.01)
85
86        assert re.match(
87            r"Took [0-9]\.[0-9]{3}s to do something",
88            logger.handlers[0].stream.getvalue())
89
90    def test_using_logger_calling_instance(self, logger):
91        timer = Timer(logger)
92        with timer():
93            time.sleep(0.01)
94
95        assert re.match(
96            r"elapsed time: [0-9]\.[0-9]{3}s",
97            logger.handlers[0].stream.getvalue())
98
99        # do it again but with custom level
100        with timer('redo it', level=logging.WARNING):
101            time.sleep(0.02)
102
103        assert re.search(
104            r"WARNING: Took [0-9]\.[0-9]{3}s to redo it",
105            logger.handlers[0].stream.getvalue())
106
107    def test_function_decorator(self, logger):
108        timer = Timer(logger)
109
110        @timer()
111        def test1():
112            time.sleep(0.01)
113        @timer('run test 2', level=logging.INFO)
114        def test2():
115            time.sleep(0.02)
116
117        test1()
118
119        assert re.match(
120            r"Took [0-9]\.[0-9]{3}s to run 'test1'",
121            logger.handlers[0].stream.getvalue())
122
123        test2()
124
125        assert re.search(
126            r"Took [0-9]\.[0-9]{3}s to run test 2",
127            logger.handlers[0].stream.getvalue())
128
129
130def test_ChannelsFilter(logger):
131    n = logger.name
132    filtr = ChannelsFilter(n+".A.B", n+".C.D")
133    handler = logger.handlers[0]
134    handler.addFilter(filtr)
135    stream = handler.stream
136
137    logging.getLogger(n+".A.B").debug('this record passes through')
138    assert 'this record passes through' in stream.getvalue()
139
140    logging.getLogger(n+'.A.B.C').debug('records from children also pass')
141    assert 'records from children also pass' in stream.getvalue()
142
143    logging.getLogger(n+'.C.D').debug('this one as well')
144    assert 'this one as well' in stream.getvalue()
145
146    logging.getLogger(n+'.A.B.').debug('also this one')
147    assert 'also this one' in stream.getvalue()
148
149    before = stream.getvalue()
150    logging.getLogger(n+'.A.F').debug('but this one does not!')
151    assert before == stream.getvalue()
152
153    logging.getLogger(n+'.C.DE').debug('neither this one!')
154    assert before == stream.getvalue()
155
156
157def test_LogMixin():
158
159    class Base(object):
160        pass
161
162    class A(LogMixin, Base):
163        pass
164
165    class B(A):
166        pass
167
168    a = A()
169    b = B()
170
171    assert hasattr(a, 'log')
172    assert hasattr(b, 'log')
173    assert isinstance(a.log, logging.Logger)
174    assert isinstance(b.log, logging.Logger)
175    assert a.log.name == "loggingTools_test.A"
176    assert b.log.name == "loggingTools_test.B"
177