Logging Muti-Progress

Posted on | Edited on | In | Comments: | Views:

Introduction:

  Recently, I have tried to record some infomations occurred during progress running automatically. Because the main language is Python, so I choose the logging module to achieve it.

  Firstly, I can record log when I use logging module. But when I tried to write log infomation two times or more, I found that the log file will be re-written with cleaning up all my infomation written last time. And then I have tested it by making two progress to write log infomating using logging module to one log file. This time I found that if the two progresses write infomation at the same time, Python Global Interpreter Lock(GIL) will prevent multiple progress form executing the I/O operations. So the fact is just one progress writted log infomation in log file.

  But why the log file will be cleaned up? I searched my question in google and found the result. Because the logging module include class TimedRotatingFileHandler(BaseRotatingHandler), and we see it sources code, strengthen the reson code:

1
2
3
4
5
6
7
8
9
10
11
12
13
def doRollover(self):
    ...
    ...
    dfn = self.rotation_filename(self.baseFilename + "." +
                                     time.strftime(self.suffix, timeTuple))
    if os.path.exists(dfn):
        os.remove(dfn)
    self.rotate(self.baseFilename, dfn)
    if self.backupCount > 0:
        for s in self.getFilesToDelete():
            os.remove(s)        
    ...
    ...

  As you see, it will remove the log file if it existed. So we try to create a class like TimedRotatingFileHandler, but support for Muti-Progress.

The coding thinking:

1
2
3
4
5
6
graph TD
a[Log file Request] --> b{shouldRollover?}
b -->|True| c[Create a new log file]
b -->|False| d[file.stream.close]
d -->f[open log file]
f --> g[if file exists, create a symlink to the currentTime log file and make the I/O stream point it.]

  When a progress request I/O operation, firstly judge it whether should Rollover? if this log file is the currenttime file you want to record it. if is True return True, while False return False. And the doRollover receive the parameter to do rollover. When it rollover, it makes a symlink pointing to the current time file and then record it.

The main code:

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
...
...
...

def shouldRollover(self, record):
        if self.currentFileName != self._compute_fn():
            return True
        return False


def _open(self):
        if self.encoding is None:
            stream = open(self.currentFileName, self.mode)
        else:
            stream = codecs.open(self.currentFileName, self.mode, self.encoding)
        # simulate file name structure of `logging.TimedRotatingFileHandler`
        if os.path.exists(self.baseFilename):
            try:
                os.remove(self.baseFilename)
            except OSError:
                pass
        try:
            # Create the symlink point the lastest log file.
            os.symlink(self.currentFileName, self.baseFilename)
        except OSError:
            pass
        return stream
...
...
...

The whole source code:

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
class MultiProcessSafeDailyRotatingFileHandler(BaseRotatingHandler):
    """
    Similar with `logging.TimedRotatingFileHandler`, while this one is
    - Multi process safe
    - Rotate at midnight only
    - Utc not supported
    - This log will create day by day.
    """
    def __init__(self, filename, encoding=None, delay=False, utc=False, **kwargs):
        self.utc = utc
        self.suffix = "%Y%m%d"
        self.baseFilename = os.path.abspath(filename)
        self.currentFileName = self._compute_fn()
        BaseRotatingHandler.__init__(self, filename, 'a', encoding, delay)

    def shouldRollover(self, record):
        if self.currentFileName != self._compute_fn():
            return True
        return False

    def doRollover(self):
        if self.stream:
            self.stream.close()
            self.stream = None
        self.currentFileName = self._compute_fn()

    def _compute_fn(self):
        return self.baseFilename + "." + time.strftime(self.suffix, time.localtime())

    def _open(self):
        if self.encoding is None:
            stream = open(self.currentFileName, self.mode)
        else:
            stream = codecs.open(self.currentFileName, self.mode, self.encoding)
        # simulate file name structure of `logging.TimedRotatingFileHandler`
        if os.path.exists(self.baseFilename):
            try:
                os.remove(self.baseFilename)
            except OSError:
                pass
        try:
            # Create the symlink point the lastest log file.
            os.symlink(self.currentFileName, self.baseFilename)
        except OSError:
            pass
        return stream

Finally

  Let me tell you some usages of logging module: This module defines functions and classes which implement a flexible event logging system for applications and libraries. The key benefit of having the logging API provided by a standard library module is that all Python modules can participate in logging, so your application log can include your own messages integrated with messages from third-party modules.

Usage:

logger –> handler –> formatter –> output

  1. Create logger

    1
    2
    logger = logging.getLogger('user')
    logger.setLevel('DEBUG')

  2. Create handler and set leverl

    1
    2
    3
        handler = logging.StreamHandler()
        handler.setLevel('DEBUG')
    `

  3. Create formatter

    1
    handler.setFormatter('%(levelname)s: %(message)s')

  4. Add to logger

    1
    logger.addHandler(handler)

My simple:

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
"""
    Author: Mikoy
    Github: github.com/MikoyChinese
    The name of the log file changes automatically based on time.
    LOGGING_CONFIG: the config file about the logging.
    <logging.config.dictConfig>: such like next,
    logger --> handler --> formatter --> output
    # Create logger
    logger = logging.getLogger('user')
    logger.setLevel('DEBUG')
    # Create handler and set leverl
    handler = logging.StreamHandler()
    handler.setLevel('DEBUG')
    # Create formatter
    handler.setFormatter('%(levelname)s: %(message)s')
    # Add to logger
    logger.addHandler(handler)
"""


from logging.handlers import BaseRotatingHandler
import os, time, codecs, logging, logging.config


class MyLogging(object):
    def __init__(self, logger_name='user'):
        # 1.The configuration below has no file to output.
        self.LOGGING_CONFIG = {
            'version': 1,
            'disable_existing_loggers': False,
            'formatters': {
                'standard': {
                    'format': '[%(levelname)s] %(asctime)s %(module)s %('
                              'process)d %(thread)d: %(message)s',
                    'datefmt': '%H:%M:%S'
                },
                'simple': {
                    'format': '[%(levelname)s]: %(message)s'
                }
            },
            'handlers': {
                'console': {
                    'level': 'DEBUG',
                    'class': 'logging.StreamHandler',
                    'formatter': 'simple'
                },
                'default': {
                    'level': 'DEBUG',
                    'class': 'loggingModule.MultiProcessSafeDailyRotatingFileHandler',
                    'formatter': 'standard',
                    'filename': './log/info.log'
                }
            },
            'loggers': {
                'user': {
                    'level': 'DEBUG',
                    'handlers': ['console', 'default']
                }
            }
        }
        # 2. To get the absolute path of the log file.
        # Log file is stored under the 'log' folder. If it not existed,
        # create it auto.
        dir_path = os.path.join(os.path.dirname(__file__), 'log')
        if not os.path.exists(dir_path):
            os.makedirs(dir_path)
        # 3. Loading the config, and make it effect.
        # This command can not be executed after the logging.getLogger function
        # because there is no specific logger name.
        logging.config.dictConfig(self.LOGGING_CONFIG)
        self.logger = logging.getLogger(logger_name)  # return a logger


class MultiProcessSafeDailyRotatingFileHandler(BaseRotatingHandler):
    """
    Similar with `logging.TimedRotatingFileHandler`, while this one is
    - Multi process safe
    - Rotate at midnight only
    - Utc not supported
    - This log will create day by day.
    """
    def __init__(self, filename, encoding=None, delay=False, utc=False, **kwargs):
        self.utc = utc
        self.suffix = "%Y%m%d"
        self.baseFilename = os.path.abspath(filename)
        self.currentFileName = self._compute_fn()
        BaseRotatingHandler.__init__(self, filename, 'a', encoding, delay)

    def shouldRollover(self, record):
        if self.currentFileName != self._compute_fn():
            return True
        return False

    def doRollover(self):
        if self.stream:
            self.stream.close()
            self.stream = None
        self.currentFileName = self._compute_fn()

    def _compute_fn(self):
        return self.baseFilename + "." + time.strftime(self.suffix, time.localtime())

    def _open(self):
        if self.encoding is None:
            stream = open(self.currentFileName, self.mode)
        else:
            stream = codecs.open(self.currentFileName, self.mode, self.encoding)
        # simulate file name structure of `logging.TimedRotatingFileHandler`
        if os.path.exists(self.baseFilename):
            try:
                os.remove(self.baseFilename)
            except OSError:
                pass
        try:
            # Create the symlink point the lastest log file.
            os.symlink(self.currentFileName, self.baseFilename)
        except OSError:
            pass
        return stream


if __name__ == '__main__':
    mylogging = MyLogging(logger_name='user')  # This is a customized class;
    while 1:
        mylogging.logger.debug('%s' % time.time())
        time.sleep(5)
Mikoy Chinese wechat
Subscribe my public wechat account by scanning.

--------------------　　　ENDING　　　--------------------