Enhanced-context-logger-oslo

Blueprint Design for (enhanced-context-logger)

Problem Statement

Currently, the logger does not provide any means to the drivers or consumers to add any additional contextual information other than the one that has been baked into the logger e.g. instanceId. The blueprint is going to add the flexibility to the logger, so that if needed the consumer of the logger could add some contextual data that can then show up in the logs without changing the individual log statements throughout the code.

Proposed Design

The idea is to introduce a placeholder for sub-contextual information. The logic would run based on the presence of such placeholder. The classes that would be enhanced in the process would be the openstack.common.log.ContextAdapter and openstack.common.log.ContextFormatter

Proposed modification to the ContextAdapter

Add a placeholder named "sub_context" within the "extra", and if found unroll it into the "extra" like below:

       extra.update({"version": self.version})
       if extra.get('sub_context', None):
           sub_context = extra.get('sub_context', None)
           for k in sub_context:
               extra.update({k:sub_context[k]})
       extra['extra'] = extra.copy()

Proposed modification to the ContextFormatter

       self._fmt += " " + CONF.logging_debug_format_suffix
       if record.__dict__.get('sub_context', None):
           sub_context = record.__dict__.get('sub_context', None)
           for k in sub_context:
               self._fmt += " [" + k + ":%(" + k + ")s]"

Proposed usage of this enhanced logger

Within a driver code, one would add the following at an appropriate place based on the information they want to add to the logger

   def _enhance_context(self, func):
       "This decorator enhances the context with a module specific contextual information"
       argnames = func.func_code.co_varnames[:func.func_code.co_argcount]
   
       def enhance_process(*args,**kwargs):
           if 'kwargs' in argnames:
               pkwargs = args[argnames.index('kwargs')]
               if 'extra' not in pkwargs:
                   pkwargs['extra'] = {}
               extra = pkwargs['extra']
               if 'sub_context' not in extra:
                   extra['sub_context'] = {}
               sub_context = extra['sub_context']            
               sub_context.update({"my_context": self._my_context_value})
           return func(*args, **kwargs)
 
       return enhance_process
 
   def _enhancelogger(self):
       setattr(logging.ContextAdapter, 'process', self._enhance_context(logging.ContextAdapter.process))

The revised logs may look like:
2014-01-17 13:09:06.815 DEBUG nova.compute.manager [-] [my_context: my_context_value] [instance: c0efa837-3a21-4b08-91f9-995e2ee2adb9] Updated the info_cache for instance from (pid=11649) _heal_instance_info_cache /opt/stack/nova/nova/compute/manager.py:4437