I want to implement per-thread logging in a multithreaded Python application using Python's logging
module. I have appended a unique ID to the logger name in the main module (which creates threads):
mylogger = logging.getLogger(str(someInt) + __name__)
This module uses multiple modules which also support logging, but have their loggers initialized like:
mylogger = logging.getLogger(__name__)
Since the callee class doesn't see the logger of caller, the logs of caller are thread-specific but that of callee go in one global file, according to its path.
What can we do to avoid changing passing str(someInt)
to each of the other modules and use them unchanged, but still log to thread-specific files?
You can set a different logging level for each logging handler but it seems you will have to set the logger's level to the "lowest". In the example below I set the logger to DEBUG, the stream handler to INFO and the TimedRotatingFileHandler to DEBUG. So the file has DEBUG entries and the stream outputs only INFO.
Log messages can have 5 levels - DEBUG, INGO, WARNING, ERROR and CRITICAL. They can also include traceback information for exceptions.
Python doesn't support multi-threading because Python on the Cpython interpreter does not support true multi-core execution via multithreading. However, Python does have a threading library. The GIL does not prevent threading.
It can be implemented by logging.Filter
, here's an example:
import threading
import logging
import logging.config
class ThreadLogFilter(logging.Filter):
"""
This filter only show log entries for specified thread name
"""
def __init__(self, thread_name, *args, **kwargs):
logging.Filter.__init__(self, *args, **kwargs)
self.thread_name = thread_name
def filter(self, record):
return record.threadName == self.thread_name
def start_thread_logging():
"""
Add a log handler to separate file for current thread
"""
thread_name = threading.Thread.getName(threading.current_thread())
log_file = '/tmp/perThreadLogging-{}.log'.format(thread_name)
log_handler = logging.FileHandler(log_file)
log_handler.setLevel(logging.DEBUG)
formatter = logging.Formatter(
"%(asctime)-15s"
"| %(threadName)-11s"
"| %(levelname)-5s"
"| %(message)s")
log_handler.setFormatter(formatter)
log_filter = ThreadLogFilter(thread_name)
log_handler.addFilter(log_filter)
logger = logging.getLogger()
logger.addHandler(log_handler)
return log_handler
def stop_thread_logging(log_handler):
# Remove thread log handler from root logger
logging.getLogger().removeHandler(log_handler)
# Close the thread log handler so that the lock on log file can be released
log_handler.close()
def worker():
thread_log_handler = start_thread_logging()
logging.info('Info log entry in sub thread.')
logging.debug('Debug log entry in sub thread.')
stop_thread_logging(thread_log_handler)
def config_root_logger():
log_file = '/tmp/perThreadLogging.log'
formatter = "%(asctime)-15s" \
"| %(threadName)-11s" \
"| %(levelname)-5s" \
"| %(message)s"
logging.config.dictConfig({
'version': 1,
'formatters': {
'root_formatter': {
'format': formatter
}
},
'handlers': {
'console': {
'level': 'INFO',
'class': 'logging.StreamHandler',
'formatter': 'root_formatter'
},
'log_file': {
'class': 'logging.FileHandler',
'level': 'DEBUG',
'filename': log_file,
'formatter': 'root_formatter',
}
},
'loggers': {
'': {
'handlers': [
'console',
'log_file',
],
'level': 'DEBUG',
'propagate': True
}
}
})
if __name__ == '__main__':
config_root_logger()
logging.info('Info log entry in main thread.')
logging.debug('Debug log entry in main thread.')
for i in xrange(3):
t = threading.Thread(target=worker,
name='Thread-{}'.format(i),
args=[])
t.start()
Console output:
$ python perThreadLoggingSample.py
2019-03-07 10:29:34,318| MainThread | INFO | Info log entry in main thread.
2019-03-07 10:29:34,320| Thread-0 | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,320| Thread-1 | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,320| Thread-2 | INFO | Info log entry in sub thread.
$
Check log files:
$ cat /tmp/perThreadLogging.log
2019-03-07 10:29:34,318| MainThread | INFO | Info log entry in main thread.
2019-03-07 10:29:34,319| MainThread | DEBUG| Debug log entry in main thread.
2019-03-07 10:29:34,320| Thread-0 | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,320| Thread-1 | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,321| Thread-0 | DEBUG| Debug log entry in sub thread.
2019-03-07 10:29:34,320| Thread-2 | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,321| Thread-1 | DEBUG| Debug log entry in sub thread.
2019-03-07 10:29:34,321| Thread-2 | DEBUG| Debug log entry in sub thread.
$
$ cat /tmp/perThreadLogging-Thread-0.log
2019-03-07 10:29:34,320| Thread-0 | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,321| Thread-0 | DEBUG| Debug log entry in sub thread.
$
$ cat /tmp/perThreadLogging-Thread-1.log
2019-03-07 10:29:34,320| Thread-1 | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,321| Thread-1 | DEBUG| Debug log entry in sub thread.
$
$ cat /tmp/perThreadLogging-Thread-2.log
2019-03-07 10:29:34,320| Thread-2 | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,321| Thread-2 | DEBUG| Debug log entry in sub thread.
$
Although, I am not really experienced in what I am suggesting, I would try to use Thread-local storage.
Thread-local storage
A class that represents thread-local data. Thread-local data are data whose values are thread specific. To manage thread-local data, just create an instance of local (or a subclass) and store attributes on it. The instance’s values will be different for separate threads.
You can then save and access the variables in the following way:
import threading
mydata = threading.local()
mydata.x = 1
I suggest to save the thread-specific logger to the thread-local variable when you create it and then access the logger again when necessary through the thread-local storage.
Have a look, it helped me to understand thread-local:
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With