Логирование и декораторы в python

база знаний
#1

 

Вопрос логирования очень часто возникает при автоматизации тестирования. Каждый кто автоматизировал больше одного теста знает, что логи это ключ к сэкономленным часам анализа ошибок и разборов поломанных тестов.

Как правильно выполнить логирование для Вашего проекта? Не знаю, каждый проект это отдельная история, которая должна рассматриваться в отдельности. (Обращайтесь, будем разбираться!) Но я хочу внести некоторые свои комментарии в данный процесс.

Меня попросили посмотреть на код и показать, как можно выводить документацию для каждого метода в лог. В python это лучше всего сделать с помощью декораторов. Декораторы – это мощная штука! В общем, меньше слов и больше кода.

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
import logging
 
def method_decorator(func):
    def wrapper(self, *argv, **kwargv):
        logging.basicConfig(filename='myapp.log', level=logging.INFO)
        logging.info(func.__doc__)
        return func(self, *argv, **kwargv)
    return wrapper
 
class Something1(object):
 
    @method_decorator
    def method1(self):
        """documentation thru method decorator for method 1"""
        pass
 
    def method2(self):
        """documentation thru method decorator for method 2"""
        pass
 
    @method_decorator
    def method3(self):
        """documentation thru method decorator for method 3"""
        pass
 
s1 = Something1()
s1.method1()
s1.method2()
s1.method3()
 
# or thru class decorator
 
def class_decorator(cls):
    for name, method in cls.__dict__.iteritems():
        if not name.startswith('_'):
            setattr(cls, name, method_decorator(method))
    return cls
 
@class_decorator
class Something2(object):
 
    def method1(self):
        """documentation thru class decorator for method 1"""
        pass
 
    def method2(self):
        """documentation thru class decorator for method 2"""
        pass
 
    def method3(self):
        """documentation thru class decorator for method 3"""
        pass
 
s2 = Something2()
s2.method1()
s2.method2()
s2.method3()
 
#check mixed execution
s1.method1()
s2.method1()

Т.е. мы описываем необходимый читабельный комментарий как docstring для методов, и когда эти методы вызываются, в лог записывается читабельная информация. В первом случае, можно использовать декоратор для методов, который можно использовать по требованию. А второй класс показывает, как можно включить данное логирование для всех методов класса. Или же Вы можете задать любую необходимую вам логику в class_decorator().

Вот, что мы получаем в логе:

1
2
3
4
5
6
7
INFO:root:documentation thru method decorator for method 1
INFO:root:documentation thru method decorator for method 3
INFO:root:documentation thru class decorator for method 1
INFO:root:documentation thru class decorator for method 2
INFO:root:documentation thru class decorator for method 3
INFO:root:documentation thru method decorator for method 1
INFO:root:documentation thru class decorator for method 1

Ну а теперь давайте подключим это к каким-то юнит-тестам. Например, это может выглядеть так.

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
import logging
import unittest
import random
from functools import wraps
 
def method_decorator(func):
    @wraps(func)
    def wrapper(self, *argv, **kwargv):
        logging.basicConfig(filename='myapp.log',
            level=logging.INFO, format='%(message)s')
        logging.info("\t- %s" % func.__doc__)
        return func(self, *argv, **kwargv)
    return wrapper
 
def class_decorator(cls):
    for name, method in cls.__dict__.iteritems():
        if not name.startswith('_'):
            setattr(cls, name, method_decorator(method))
    return cls
 
class MyTestingException(Exception):
 
    def __init__(self, value):
        self.msg = value
 
    def __str__(self):
        return "%s\n%s" % (self.msg, open("myapp.log").read())
 
@class_decorator
class Something(object):
 
    def _generate_number(self):
        if random.randint(0, 10) == 5:
            raise MyTestingException("Please have a look to details:")
        return random.randint(0, 2)
 
    def method1(self):
        """log to system to make some actions"""
        return self._generate_number()
 
    def method2(self):
        """registered account with additional credits"""
        return self._generate_number()
 
    def method3(self):
        """buy subscription for defined account"""
        return self._generate_number()
 
class TestSomething(unittest.TestCase):
 
    def setUp(self):
        with open("myapp.log", "w") as f:
            f.truncate()
        self.s = Something()
        self.data = {'some data': [1, 2, 3]}
 
    def test_method1(self):
        self.s.method1()
        self.s.method2()
        self.s.method3()
        self.assertEquals(self.s.method1(), 0)
 
    def test_method2(self):
        self.s.method3()
        self.s.method2()
        self.s.method1()
        self.assertEquals(self.s.method2(), 1)
 
    def test_method3(self):
        self.s.method1()
        self.s.method3()
        self.s.method2()
        self.assertEquals(self.s.method3(), 2)
 
if __name__ == '__main__':
    unittest.main()

Что дает следующие результаты:

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
EFE
 
======================================================================
 
ERROR: test_method1 (__main__.TestSomething)
 
----------------------------------------------------------------------
 
Traceback (most recent call last):
 
  File "demo.py", line 64, in test_method1
 
    self.s.method3()
 
  File "demo.py", line 12, in wrapper
 
    return func(self, *argv, **kwargv)
 
  File "demo.py", line 50, in method3
 
    return self._generate_number()
 
  File "demo.py", line 37, in _generate_number
 
    raise MyTestingException("Please have a look to details:")
 
MyTestingException: Please have a look to details:
 
    - log to system to make some actions
 
    - registered account with additional credits
 
    - buy subscription for defined account
 
======================================================================
 
ERROR: test_method3 (__main__.TestSomething)
 
----------------------------------------------------------------------
 
Traceback (most recent call last):
 
  File "demo.py", line 77, in test_method3
 
    self.assertEquals(self.s.method3(), 2)
 
  File "demo.py", line 12, in wrapper
 
    return func(self, *argv, **kwargv)
 
  File "demo.py", line 50, in method3
 
    return self._generate_number()
 
  File "demo.py", line 37, in _generate_number
 
    raise MyTestingException("Please have a look to details:")
 
MyTestingException: Please have a look to details:
 
    - log to system to make some actions
 
    - buy subscription for defined account
 
    - registered account with additional credits
 
    - buy subscription for defined account
 
======================================================================
 
FAIL: test_method2 (__main__.TestSomething)
 
----------------------------------------------------------------------
 
Traceback (most recent call last):
 
  File "demo.py", line 71, in test_method2
 
    self.assertEquals(self.s.method2(), 1)
 
AssertionError: 2 != 1
 
----------------------------------------------------------------------
 
Ran 3 tests in 0.003s
 
FAILED (failures=1, errors=2)

Как всегда, пишите, если у Вас есть вопросы! Удачи и хорошего Вам питонирования! :)

#2

О, будет полезным, с декораторами ещё не разбирался. + за пост