From 29141af3a937986b94c0ee8df0ec4263f3215c09 Mon Sep 17 00:00:00 2001
From: Cosimo Lupo <cosimo.lupo@daltonmaag.com>
Date: Mon, 16 Jan 2017 14:44:08 +0000
Subject: [PATCH] [Tests] convert loggingTools doctests into loggingTools.py

---
 Tests/misc/loggingTools_test.py | 151 ++++++++++++++++++++++++++++++++
 1 file changed, 151 insertions(+)
 create mode 100644 Tests/misc/loggingTools_test.py

diff --git a/Tests/misc/loggingTools_test.py b/Tests/misc/loggingTools_test.py
new file mode 100644
index 000000000..092c91bbf
--- /dev/null
+++ b/Tests/misc/loggingTools_test.py
@@ -0,0 +1,151 @@
+from __future__ import print_function, division, absolute_import
+from fontTools.misc.py23 import *
+from fontTools.misc.loggingTools import (
+    LevelFormatter, Timer, configLogger, ChannelsFilter)
+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 fist_lap >= 0.01
+        assert timer.elapsed == fist_lap
+        time.sleep(0.02)
+        second_lap = timer.split()
+        assert second_lap >= 0.02
+        assert timer.elapsed == second_lap
+
+    def test_time(self):
+        timer = Timer()
+        time.sleep(0.01)
+        overall_time = timer.time()
+        assert overall_time >= 0.01
+
+    def test_context_manager(self):
+        with Timer() as t:
+            time.sleep(0.01)
+        assert t.elapsed >= 0.01
+
+    def test_using_logger(self, logger):
+        with Timer(logger, 'do something'):
+            time.sleep(0.01)
+
+        assert re.match(
+            "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(
+            "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(
+            "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(
+            "Took [0-9]\.[0-9]{3}s to run 'test1'",
+            logger.handlers[0].stream.getvalue())
+
+        test2()
+
+        assert re.search(
+            "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()