Python has a standard logging library. I used that with configuration file (.conf) that is useful for have configuration point with separating it from application code.
Environment
- MacOS Catalina 10.15.7
- Python 3.9.7
1. Simple file output for debugging
A simple example for logging file with configuration is:
logging.conf
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
|
[loggers]
keys=root
[handlers]
keys=fileHandler
[logger_root]
handlers=fileHandler
level=DEBUG
[handler_fileHandler]
class=handlers.TimedRotatingFileHandler
level=DEBUG
formatter=logFormatter
args=('sample.log', 'D')
[formatters]
keys=logFormatter
[formatter_logFormatter]
class=logging.Formatter
format=%(asctime)s %(thread)d %(levelname)s %(filename)s %(funcName)s %(lineno)d %(message)s
|
sample.py
1
2
3
4
5
6
7
8
9
10
|
from logging import config, getLogger
config.fileConfig('logging.conf')
logger = getLogger(__name__)
def main():
logger.debug("this is logged by main()")
if __name__ == '__main__':
main()
|
Output in sample.log is like:
1
|
2021-10-21 10:38:10,416 4378643904 DEBUG sample.py main 7 this is logged by main()
|
Though logging has variety of functions in filtering like log level and parent/child formatter, I want to concentrate on log record content here because it’s important for developer to have sufficient information in debug record.
The content in log record is defined in formatter section in configuration. I selected some with referring LogRecord attributes in documentation.
Not only general information like actime, levelname, I need to include
thread : for some async function in applicationfilename, funcNmae, lineno : for specifying where the issue happens in code
Tip
There are other options for useful information in debug record.
name is a logger name. getLogger(__name__) retrieves module name. If that is predefined, the record returns __main__. if the logger name is not specified by getLogger(), the record returns root.filepath is full path for the module file that calls logger.
2. Multiple loggers for different modules
Add following logger information for the other module.
logging2.conf
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
|
[loggers]
keys=root, sample2_called
[handlers]
keys=fileHandler
[logger_root]
handlers=fileHandler
level=DEBUG
[logger_sample2_called]
handlers=fileHandler
level=DEBUG
qualname=sample2_called
propagate=0
[handler_fileHandler]
class=handlers.TimedRotatingFileHandler
level=DEBUG
formatter=logFormatter
args=('sample2.log', 'D')
[formatters]
keys=logFormatter
[formatter_logFormatter]
class=logging.Formatter
format=%(asctime)s %(thread)d %(levelname)s %(filename)s %(name)s %(funcName)s %(lineno)d %(message)s
// ... code
|
It’s necessary to add qualname, that is the name for the logger called by the application. In this case, the name is __name__ in sample2_called.py.
If you do not add propagate or set propagate=1, that means propagate the logger behavior to parent logger (root logger). So, the log file has duplicated lines of log records.
sample2.py
1
2
3
4
5
6
7
8
9
10
11
12
|
from logging import config, getLogger
from sample2_called import sample2_func
config.fileConfig('logging2.conf')
logger = getLogger(__name__)
def main():
logger.debug("this is logged by main()")
sample2_func()
if __name__ == '__main__':
main()
|
sample2_called.py
1
2
3
4
5
6
|
from logging import config, getLogger
logger = getLogger(__name__)
def sample2_func():
logger.debug("this is logged by sample2_called")
|
Output in sample2.log is:
1
2
|
2021-10-21 11:34:14,075 4352720320 DEBUG sample2.py __main__ main 9 this is logged by main()
2021-10-21 11:34:14,075 4352720320 DEBUG sample2_called.py sample2_called sample2_func 7 this is logged by sample2_called
|
3. Single logger for different modules
Tip
Above setting in
2. Multiple loggers for different modules requires to configure logger to every module that calls logger. For solving this, make one logger and call it from every module instead of calling
getLogger(__name__) in many examples in internet.
logging3.conf
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
|
[loggers]
keys=root, sampleLogger
[handlers]
keys=fileHandler
[logger_root]
handlers=fileHandler
level=DEBUG
[logger_sampleLogger]
handlers=fileHandler
level=DEBUG
qualname=sampleLogger
propagate=0
[handler_fileHandler]
class=handlers.TimedRotatingFileHandler
level=DEBUG
formatter=logFormatter
args=('sample3.log', 'D')
[formatters]
keys=logFormatter
[formatter_logFormatter]
class=logging.Formatter
format=%(asctime)s %(thread)d %(levelname)s %(filename)s %(funcName)s %(lineno)d %(message)s
|
sample3.py
1
2
3
4
5
6
7
8
9
10
11
12
13
|
from logging import config, getLogger
from sample3_called import sample3_func
config.fileConfig('logging3.conf')
#logger = getLogger()
logger = getLogger("sampleLogger")
def main():
logger.debug("this is logged by main()")
sample3_func()
if __name__ == '__main__':
main()
|
sample3_called.py
1
2
3
4
5
6
|
from logging import getLogger
logger = getLogger("sampleLogger")
def sample3_func():
logger.debug("this is logged by sample3_called")
|
Output in sample3.log
1
2
|
2021-10-21 12:28:48,577 4647820736 DEBUG sample3.py main 9 this is logged by main()
2021-10-21 12:28:48,578 4647820736 DEBUG sample3_called.py sample3_func 6 this is logged by sample3_called
|
In this case, %(name)s in log record attribute is omitted because it’s useless when every line has the same value of logger name.
4. Logger with different handlers
For debugging, sometime I need information in standard output with adding condoleHandler.
logging4.conf
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
|
[loggers]
keys=root, sampleLogger
[handlers]
keys=fileHandler, consoleHandler
[logger_root]
handlers=fileHandler, consoleHandler
level=DEBUG
[logger_sampleLogger]
handlers=fileHandler, consoleHandler
level=DEBUG
qualname=sampleLogger
propagate=0
[handler_fileHandler]
class=handlers.TimedRotatingFileHandler
level=DEBUG
formatter=logFormatter
args=('sample4.log', 'D')
[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=logFormatter
args=(sys.stdout, )
[formatters]
keys=logFormatter
[formatter_logFormatter]
class=logging.Formatter
format=%(asctime)s %(thread)d %(levelname)s %(filename)s %(funcName)s %(lineno)d %(message)s
|
Both standard output and log file has the same records like: :
1
2
3
|
$ python sample4.py
2021-10-21 12:40:50,662 4386287040 DEBUG sample4.py main 9 this is logged by main()
2021-10-21 12:40:50,663 4386287040 DEBUG sample4_called.py sample4_func 6 this is logged by sample4_called
|
Sources
Sample codes are uploaded in github
References