TabPy logs are useful for investigating issues, learning about user activities, how TabPy is used and so on. In my previous post TabPy: modifying default configuration I showed how to change TabPy settings. Logging for TabPy is configured in a similar way and I am going to show and explain some details for how to configure logging.
For the most recent and complete documentation about Python logger configuration, read this documentation page – https://docs.python.org/3/howto/logging.html.
In TabPy config file logger (or rather loggers) are configured with a few sections. A logger itself associated with a logger handler which in its turn depends on a logger formatter:
- Loggers are used in Python code to initiate logging a message. Based on the severity logger passes the message to corresponding handlers.
- Handlers are dispatching log messages to the handler’s specified destination. There are handlers for the console, files, etc.
- Formatters specify how a logged message should look like: order and format of the message properties.
For logger configuration file format read the documentation at https://docs.python.org/3/library/logging.config.html#configuration-file-format.
Following is the example of how to configure logging.
First, section to look at is [loggers] where names of loggers are listed (TabPy will log with all of them). The following example specifies 2 loggers:
[loggers]
keys=root,fileLogger
NOTE: there have to be a logger (it can be the only logger) named “root” in the list of loggers.
Next is the [handlers] section which lists handlers:
[handlers]
keys=consoleHandler,fileHandler
And finally formatters section [formatter] lists all the formatters (not all of them have to be used):
[formatters]
keys=consoleFormatter,fileFormatter
Now for each logger in [logger] section there is [logger_<name>] section with settings for a logger:
[logger_root]
level=WARNING
handlers=consoleHandler
[logger_fileLogger]
level=DEBUG
handlers=fileHandler
propgate=1
qualname=consoleLogger
As you can see from the example above for each logger severity level is specified which means only messages with specified severity of higher. The level can be one of DEBUG, INFO, WARNING, ERROR, CRITICAL or NOTSET (all messages will be logged).
Handlers for a logger are listed with handlers parameter. It is possible to have more than one handler for a logger.
For non-root loggers properties propgate and qualname need to be set. The first one specifies if messages need to be propagated to a handler higher up and is set to 1 or 0. And qualname sets the name for the logger so it can be referenced from Python code.
For each handler there is [handler_<name>] section:
[handler_consoleHandler]
class=StreamHandler
level=WARNING
formatter=consoleFormatter
args=(sys.stdout,)
[handler_fileHandler]
class=handlers.RotatingFileHandler
level=DEBUG
formatter=fileFormatter
args=('tabpy_log.log', 'a', 1000000, 5)
For each formatter there is level parameter which is configured in the same way as for a logger.
With class parameter a Python class which implements a handler is specified (more details below). It is possible to use the same class for different handlers. As an example, you can have one large log file where entries are appended and the same messages logged to date specific log files.
Formatter for logged messages is set with formatter parameter. Again – the same formatter can be used with multiple handlers.
And args parameter provides logger specific parameters.
Handler classes available with Python are listed at https://docs.python.org/3/library/logging.handlers.html#module-logging.handlers, but it is possible to use any custom handlers (e.g. for colorful output in the console) with other packages installed in the Python environment. Some useful handlers are:
StreamHandler sends logging to a stream (e.g. console).FileHandler appends messages to a file.NullHandler does not log anything.RotatingFileHandler logs to a file until log file size limit is reached and then creates a new file and logs to it. The handler is used in the example above and it will create a new log file when the current one reaches 1000000 bytes in size. The current file name is always tabpy_log.log, previous log file will be named tabpy_log.log.1 and so on till tabpy_log.log.5.TimedRotatingFileHandler is similar to RotatingFileHandler but creates a new file after the specified time interval.HTTPHandler sends messages to a web server with GET or POST command.
For each formatter printf-style string formatting string (documentation is here – https://docs.python.org/3/library/stdtypes.html#old-string-formatting) specifies how the format message is built. In the format string additional log objects can be used (list of the log objects is here – https://docs.python.org/3/library/logging.html#logging.LogRecord):
[formatter_consoleFormatter]
format=%(asctime)s: %(message)s
datefmt=%H:%M:%S
[formatter_fileFormatter]
format=%(asctime)s [%(levelname)s] (%(filename)s:%(module)s:%(lineno)d): %(message)s
datefmt=%Y-%m-%d,%H:%M:%S
In this example console formatter will output all the messages with preceding timestamp and for file logs there will be date-time stamp, severity of the message, where in the code it was logged from and the message itself.
Now the whole config file (I have it on my machine saved as c:\demo\tabpy\tabpy.conf:
[loggers]
keys=root,fileLogger
[formatters]
keys=consoleFormatter,fileFormatter
[handlers]
keys=consoleHandler,fileHandler
[logger_root]
level=WARNING
handlers=consoleHandler
[logger_fileLogger]
level=DEBUG
handlers=fileHandler
propgate=1
qualname=consoleLogger
[handler_consoleHandler]
class=StreamHandler
level=WARNING
formatter=consoleFormatter
args=(sys.stdout,)
[handler_fileHandler]
class=handlers.RotatingFileHandler
level=DEBUG
formatter=fileFormatter
args=('tabpy_log.log', 'a', 1000000, 5)
[formatter_consoleFormatter]
format=%(asctime)s: %(message)s
datefmt=%H:%M:%S
[formatter_fileFormatter]
format=%(asctime)s [%(levelname)s] (%(filename)s:%(module)s:%(lineno)d): %(message)s
datefmt=%Y-%m-%d,%H:%M:%S
Starting TabPy with the config:
tabpy --config c:\demo\tabpy\tabpy.conf
After running a few requests against my local TabPy instance this is what I see in the console:
15:19:37: Responding with status=404, message="Unknown endpoint", info="Endpoint olek_add is not found"
15:19:37: 404 GET /endpoints/olek_add (::1) 5.03ms
And for the same TabPy there’s much much more information in tabpy_log.log file:
2019-12-04,15:14:54 [DEBUG] (app.py:app:215): Parameter port set to "9004" from default value
2019-12-04,15:14:54 [DEBUG] (app.py:app:215): Parameter server_version set to "0.8.9" from default value
2019-12-04,15:14:54 [DEBUG] (app.py:app:215): Parameter evaluate_timeout set to "30" from default value
...
2019-12-04,15:15:17 [INFO] (app.py:app:110): Initializing TabPy...
...
2019-12-04,15:15:17 [INFO] (app.py:app:93): Web service listening on port 9004
