aboutsummaryrefslogtreecommitdiff
path: root/Tests/misc/loggingTools_test.py
blob: fd13044cd89f0c5d1be6158fe5e0118a7471a387 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
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
50
51
52
53
54
55
56
57
58
59
60
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
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
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
from fontTools.misc.loggingTools import (
    LevelFormatter,
    Timer,
    configLogger,
    ChannelsFilter,
    LogMixin,
)
from io import StringIO
import logging
import textwrap
import time
import re
import pytest


def logger_name_generator():
    basename = "fontTools.test#"
    num = 1
    while True:
        yield basename+str(num)
        num += 1

unique_logger_name = logger_name_generator()


@pytest.fixture
def logger():
    log = logging.getLogger(next(unique_logger_name))
    configLogger(logger=log, level="DEBUG", stream=StringIO())
    return log


def test_LevelFormatter():
    stream = StringIO()
    handler = logging.StreamHandler(stream)
    formatter = LevelFormatter(
        fmt={
            '*':     '[%(levelname)s] %(message)s',
            'DEBUG': '%(name)s [%(levelname)s] %(message)s',
            'INFO':  '%(message)s',
        })
    handler.setFormatter(formatter)
    name = next(unique_logger_name)
    log = logging.getLogger(name)
    log.setLevel(logging.DEBUG)
    log.addHandler(handler)

    log.debug("this uses a custom format string")
    log.info("this also uses a custom format string")
    log.warning("this one uses the default format string")

    assert stream.getvalue() == textwrap.dedent("""\
        %s [DEBUG] this uses a custom format string
        this also uses a custom format string
        [WARNING] this one uses the default format string
        """ % name)


class TimerTest(object):

    def test_split(self):
        timer = Timer()
        time.sleep(0.01)
        fist_lap =  timer.split()
        assert timer.elapsed == fist_lap
        time.sleep(0.1)
        second_lap = timer.split()
        assert second_lap > fist_lap
        assert timer.elapsed == second_lap

    def test_time(self):
        timer = Timer()
        time.sleep(0.01)
        overall_time = timer.time()
        assert overall_time > 0

    def test_context_manager(self):
        with Timer() as t:
            time.sleep(0.01)
        assert t.elapsed > 0

    def test_using_logger(self, logger):
        with Timer(logger, 'do something'):
            time.sleep(0.01)

        assert re.match(
            r"Took [0-9]\.[0-9]{3}s to do something",
            logger.handlers[0].stream.getvalue())

    def test_using_logger_calling_instance(self, logger):
        timer = Timer(logger)
        with timer():
            time.sleep(0.01)

        assert re.match(
            r"elapsed time: [0-9]\.[0-9]{3}s",
            logger.handlers[0].stream.getvalue())

        # do it again but with custom level
        with timer('redo it', level=logging.WARNING):
            time.sleep(0.02)

        assert re.search(
            r"WARNING: Took [0-9]\.[0-9]{3}s to redo it",
            logger.handlers[0].stream.getvalue())

    def test_function_decorator(self, logger):
        timer = Timer(logger)

        @timer()
        def test1():
            time.sleep(0.01)
        @timer('run test 2', level=logging.INFO)
        def test2():
            time.sleep(0.02)

        test1()

        assert re.match(
            r"Took [0-9]\.[0-9]{3}s to run 'test1'",
            logger.handlers[0].stream.getvalue())

        test2()

        assert re.search(
            r"Took [0-9]\.[0-9]{3}s to run test 2",
            logger.handlers[0].stream.getvalue())


def test_ChannelsFilter(logger):
    n = logger.name
    filtr = ChannelsFilter(n+".A.B", n+".C.D")
    handler = logger.handlers[0]
    handler.addFilter(filtr)
    stream = handler.stream

    logging.getLogger(n+".A.B").debug('this record passes through')
    assert 'this record passes through' in stream.getvalue()

    logging.getLogger(n+'.A.B.C').debug('records from children also pass')
    assert 'records from children also pass' in stream.getvalue()

    logging.getLogger(n+'.C.D').debug('this one as well')
    assert 'this one as well' in stream.getvalue()

    logging.getLogger(n+'.A.B.').debug('also this one')
    assert 'also this one' in stream.getvalue()

    before = stream.getvalue()
    logging.getLogger(n+'.A.F').debug('but this one does not!')
    assert before == stream.getvalue()

    logging.getLogger(n+'.C.DE').debug('neither this one!')
    assert before == stream.getvalue()


def test_LogMixin():

    class Base(object):
        pass

    class A(LogMixin, Base):
        pass

    class B(A):
        pass

    a = A()
    b = B()

    assert hasattr(a, 'log')
    assert hasattr(b, 'log')
    assert isinstance(a.log, logging.Logger)
    assert isinstance(b.log, logging.Logger)
    assert a.log.name == "loggingTools_test.A"
    assert b.log.name == "loggingTools_test.B"