Of Stack

Python adds context information to the log output

  • 2020-06-01 10:20:13
  • OfStack

In addition to the parameters passed to the logging function, such as msg, we sometimes want to include some extra context information in the log output. For example, in a web application, you might want to log client specific information, such as the IP address and user name of the remote client. Here we introduce the following implementation methods:

Introduce context information by passing an extra parameter to the logging function Introduce context information using LoggerAdapters Introduce context information using Filters

1. Introduce context information by passing an extra parameter to the logging function

As mentioned earlier, you can add additional context information to the log output by passing an extra parameter to the logging function, such as: 


import logging
import sys
fmt = logging.Formatter("%(asctime)s - %(name)s - %(ip)s - %(username)s - %(message)s")
h_console = logging.StreamHandler(sys.stdout)
h_console.setFormatter(fmt)
logger = logging.getLogger("myPro")
logger.setLevel(logging.DEBUG)
logger.addHandler(h_console)
extra_dict = {"ip": "113.208.78.29", "username": "Petter"}
logger.debug("User Login!", extra=extra_dict)
extra_dict = {"ip": "223.190.65.139", "username": "Jerry"}
logger.info("User Access!", extra=extra_dict)

Output:

2017-05-14 15:47:25,562 - myPro - 113.208.78.29 - Petter - User Login!
2017-05-14 15:47:25,562 - myPro - 223.190.65.139 - Jerry - User Access!

This is not a convenient way to pass information, however, because each call to the logging method passes an extra keyword parameter. This is true even if there is no context information to insert, because the fields specified in formatter for this logger setting must exist. Therefore, we recommend the following two ways to introduce context information.

You might try to solve the problem above by creating one instance of Logger each time you create a connection, but this is obviously not a good solution because these instances of Logger are not garbage collected. Although this is not a problem in practice, it can be very difficult to manage when the number of Logger becomes uncontrollable.

2. Use LoggerAdapters to introduce context information

Using the LoggerAdapter class to pass context information to the information in the log event is a very simple way to think of it as an optimized version of the first implementation -- because it provides a default value for extra. This class is designed to be similar to Logger, so we can call the debug(), info(), warning(),error(), exception(), critical(), and log() methods as if we were using instances of the Logger class. When creating an instance of LoggerAdapter, we need to pass an instance of Logger and a dictionary object containing context information to the instance building method of the class. When one of the logging methods of an LoggerAdapter instance is called, the method, after processing the log logging message and the dictionary object, calls the same logging method of the logger object passed to the instance when the instance was built. Here are the definitions of several methods in the LoggerAdapter class: 


class LoggerAdapter(object):
 """
 An adapter for loggers which makes it easier to specify contextual
 information in logging output.
 """
 def __init__(self, logger, extra):
  """
  Initialize the adapter with a logger and a dict-like object which
  provides contextual information. This constructor signature allows
  easy stacking of LoggerAdapters, if so desired.
  You can effectively pass keyword arguments as shown in the
  following example:
  adapter = LoggerAdapter(someLogger, dict(p1=v1, p2="v2"))
  """
  self.logger = logger
  self.extra = extra
 def process(self, msg, kwargs):
  """
  Process the logging message and keyword arguments passed in to
  a logging call to insert contextual information. You can either
  manipulate the message itself, the keyword args or both. Return
  the message and kwargs modified (or not) to suit your needs.
  Normally, you'll only need to override this one method in a
  LoggerAdapter subclass for your specific needs.
  """
  kwargs["extra"] = self.extra
  return msg, kwargs
 def debug(self, msg, *args, **kwargs):
  """
  Delegate a debug call to the underlying logger, after adding
  contextual information from this adapter instance.
  """
  msg, kwargs = self.process(msg, kwargs)
  self.logger.debug(msg, *args, **kwargs)

By analyzing the above code, the following conclusions can be drawn:

The context information is added to the logged output message in the process() method of the LoggerAdapter class. To implement the custom requirement, simply implement a subclass of LoggerAdapter and override the process() method. In the default implementation of the process() method, the value of msg is not modified, but an key named extra is inserted for the keyword parameter. The value of extra is the parameter value passed to the LoggerAdapter class constructor. The extra parameters received by the LoggerAdapter class building method are actually the default context information provided to meet the formatter format requirements of logger.

With regard to the third conclusion mentioned above, let's take a look at an example: 


import logging
import sys
#  Initialize the 1 One has to be passed to LoggerAdapter constructional logger The instance 
fmt = logging.Formatter("%(asctime)s - %(name)s - %(ip)s - %(username)s - %(message)s")
h_console = logging.StreamHandler(sys.stdout)
h_console.setFormatter(fmt)
init_logger = logging.getLogger("myPro")
init_logger.setLevel(logging.DEBUG)
init_logger.addHandler(h_console)
#  Initialize the 1 One has to be passed to LoggerAdapter The context dictionary object for the constructor 
extra_dict = {"ip": "IP", "username": "USERNAME"}
#  To obtain 1 a LoggerAdapter Instances of the class 
logger = logging.LoggerAdapter(init_logger, extra_dict)
#  Logging method calls in the application 
logger.info("User Login!")
logger.info("User Login!", extra={"ip": "113.208.78.29", "username": "Petter"})
logger.extra = {"ip": "113.208.78.29", "username": "Petter"}
logger.info("User Login!")
logger.info("User Login!")

Output results: 


#  use extra Default value: {"ip": "IP", "username": "USERNAME"}
2017-05-14 17:23:15,148 - myPro - IP - USERNAME - User Login!
# info(msg, extra) Passed in the method extra Method does not override the default values 
2017-05-14 17:23:15,148 - myPro - IP - USERNAME - User Login!
# extra The default values have been changed 
2017-05-14 17:23:15,148 - myPro - 113.208.78.29 - Petter - User Login!
2017-05-14 17:23:15,148 - myPro - 113.208.78.29 - Petter - User Login!

Output according to the above procedures, we will find a problem: pass to LoggerAdapter class constructor extra parameter values cannot be LoggerAdapter instance of logging function (such as the above call info () method) extra parameters of the cover, can only be amended by LoggerAdapter instance extra attribute to modify the default values (such as the use of logger. extra = xxx), but it also means that the default value is modified.

The idea is to implement a subclass of LoggerAdapter and override the process() method. The operation of kwargs parameter should first determine whether it contains the extra keyword. If it does, the default value will not be used to replace it. Take the default value if the kwargs parameter does not contain the extra keyword. Let's look at the implementation: 


import logging
import sys
class MyLoggerAdapter(logging.LoggerAdapter):
 def process(self, msg, kwargs):
  if 'extra' not in kwargs:
   kwargs["extra"] = self.extra
  return msg, kwargs
if __name__ == '__main__':
 #  Initialize the 1 One has to be passed to LoggerAdapter constructional logger The instance 
 fmt = logging.Formatter("%(asctime)s - %(name)s - %(ip)s - %(username)s - %(message)s")
 h_console = logging.StreamHandler(sys.stdout)
 h_console.setFormatter(fmt)
 init_logger = logging.getLogger("myPro")
 init_logger.setLevel(logging.DEBUG)
 init_logger.addHandler(h_console)
 #  Initialize the 1 One has to be passed to LoggerAdapter The context dictionary object for the constructor 
 extra_dict = {"ip": "IP", "username": "USERNAME"}
 #  To obtain 1 A custom LoggerAdapter Instances of the class 
 logger = MyLoggerAdapter(init_logger, extra_dict)
 #  Logging method calls in the application 
 logger.info("User Login!")
 logger.info("User Login!", extra={"ip": "113.208.78.29", "username": "Petter"})
 logger.info("User Login!")
 logger.info("User Login!")

Output results: 


#  use extra Default value: {"ip": "IP", "username": "USERNAME"}
2017-05-22 17:35:38,499 - myPro - IP - USERNAME - User Login!
# info(msg, extra) Passed in the method extra Method overrides the default value 
2017-05-22 17:35:38,499 - myPro - 113.208.78.29 - Petter - User Login!
# extra The default value remains the same 
2017-05-22 17:35:38,499 - myPro - IP - USERNAME - User Login!
2017-05-22 17:35:38,499 - myPro - IP - USERNAME - User Login!

OK! Problem solved.

In fact, if we want to achieve free field insertion in the log output without being restricted by formatter, we can concatenate the keyword information in the dictionary parameter into the message of the log event in the process() method of a subclass of custom LoggerAdapter. Obviously, the location of the field information in these contexts in the log output is limited. The advantage of using 'extra' is that the value of this class dictionary object will be merged into the s 108en__ of this LogRecord instance, allowing us to customize the format string of the log output with the Formatter instance. This makes the location of the field information in the context information in the log output as flexible as the location of the built-in field 1, but only if the key in the class dictionary object passed to the constructor method is deterministic and explicit.

3. Use Filters to introduce context information

In addition, we can modify the passed LogRecord instance in the filter(record) method using a custom Filter.Filter instance and assign the added context information to the instance as a new property, so that we can output this context information by specifying the string format of formatter.

Imitating the above implementation, we added two pieces of information related to the current network request in the LogRecord instance passing the filter(record) method: ip and username. 


import logging
from random import choice
class ContextFilter(logging.Filter):
  ip = 'IP'
  username = 'USER'
  def filter(self, record):
   record.ip = self.ip
   record.username = self.username
   return True
if __name__ == '__main__':
 levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)
 users = ['Tom', 'Jerry', 'Peter']
 ips = ['113.108.98.34', '219.238.78.91', '43.123.99.68']
 logging.basicConfig(level=logging.DEBUG,
      format='%(asctime)-15s %(name)-5s %(levelname)-8s %(ip)-15s %(username)-8s %(message)s')
 logger = logging.getLogger('myLogger')
 f = ContextFilter()
 logger.addFilter(f)
 logger.debug('A debug message')
 logger.info('An info message with %s', 'some parameters')
 for x in range(5):
  lvl = choice(levels)
  lvlname = logging.getLevelName(lvl)
  filter.ip = choice(ips)
  filter.username = choice(users)
  logger.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')

Output results:

2017-05-15 10:21:49,401 myLogger DEBUG IP USER A debug message
2017-05-15 10:21:49,401 myLogger INFO IP USER An info message with some parameters
2017-05-15 10:21:49,401 myLogger INFO 219.238.78.91 Tom A message at INFO level with 2 parameters
2017-05-15 10:21:49,401 myLogger INFO 219.238.78.91 Peter A message at INFO level with 2 parameters
2017-05-15 10:21:49,401 myLogger DEBUG 113.108.98.34 Jerry A message at DEBUG level with 2 parameters
2017-05-15 10:21:49,401 myLogger CRITICAL 43.123.99.68 Tom A message at CRITICAL level with 2 parameters
2017-05-15 10:21:49,401 myLogger INFO 43.123.99.68 Jerry A message at INFO level with 2 parameters

Note: in a real web application, you might want to consider thread safety when multiple threads are concurrent. You can save connection information or instances of custom filters to one threadlocal via threading.local.

Related articles: