Logging Muti-Progress
<center>
Author: Mikoy Date: 2018-08-25
</center>
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:
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:
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:
...
...
...
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:
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
- 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)
My simple:
"""
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)
