Minimally invasive set of logging fixes
- Cache structlog logger, make formatters generic
- Fix consul-specific naming in coordinator code
- Fix logging statements in envoyd that require formatting
- Clean up unicode-invalid binary strings from etcd
- Structured 'msg' key is removed by logging framework, change name
in a few places
- Move logging from INFO and above levels to DEBUG in a few places
Change-Id: Iea40f4969ad328f3d1180533dfc35cb9a2c0756b
diff --git a/common/structlog_setup.py b/common/structlog_setup.py
index cbbda89..a6950b7 100644
--- a/common/structlog_setup.py
+++ b/common/structlog_setup.py
@@ -18,59 +18,20 @@
import logging
import logging.config
-from collections import OrderedDict
import structlog
-from structlog.stdlib import BoundLogger, INFO
-
-try:
- from thread import get_ident as _get_ident
-except ImportError:
- from dummy_thread import get_ident as _get_ident
-class StructuredLogRenderer(object):
- def __call__(self, logger, name, event_dict):
- # in order to keep structured log data in event_dict to be forwarded as
- # is, we need to pass it into the logger framework as the first
- # positional argument.
- args = (event_dict,)
- kwargs = {}
- return args, kwargs
-
-
-class PlainRenderedOrderedDict(OrderedDict):
- """Our special version of OrderedDict that renders into string as a dict,
- to make the log stream output cleaner.
- """
- def __repr__(self, _repr_running={}):
- 'od.__repr__() <==> repr(od)'
- call_key = id(self), _get_ident()
- if call_key in _repr_running:
- return '...'
- _repr_running[call_key] = 1
- try:
- if not self:
- return '{}'
- return '{%s}' % ", ".join("%s: %s" % (k, v)
- for k, v in self.items())
- finally:
- del _repr_running[call_key]
-
-
-def setup_logging(log_config, instance_id, verbosity_adjust=0):
+def setup_logging(log_config, instance_id,
+ verbosity_adjust=0, cache_on_use=True):
"""
Set up logging such that:
- The primary logging entry method is structlog
(see http://structlog.readthedocs.io/en/stable/index.html)
- - By default, the logging backend is Python standard lib logger
+ - Optionally cache the logger on first use
+ :return: structured logger
"""
- def add_exc_info_flag_for_exception(_, name, event_dict):
- if name == 'exception':
- event_dict['exc_info'] = True
- return event_dict
-
def add_instance_id(_, __, event_dict):
event_dict['instance_id'] = instance_id
return event_dict
@@ -79,34 +40,34 @@
logging.config.dictConfig(log_config)
logging.root.level -= 10 * verbosity_adjust
- processors = [
- add_exc_info_flag_for_exception,
- structlog.processors.StackInfoRenderer(),
- structlog.processors.format_exc_info,
- add_instance_id,
- StructuredLogRenderer(),
- ]
- structlog.configure(logger_factory=structlog.stdlib.LoggerFactory(),
- context_class=PlainRenderedOrderedDict,
- wrapper_class=BoundLogger,
- processors=processors)
+ structlog.configure(
+ processors=[
+ structlog.stdlib.filter_by_level,
+ structlog.stdlib.PositionalArgumentsFormatter(),
+ structlog.processors.StackInfoRenderer(),
+ structlog.processors.format_exc_info,
+ add_instance_id,
+ structlog.processors.UnicodeEncoder(),
+ structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+ ],
+ context_class=dict,
+ logger_factory=structlog.stdlib.LoggerFactory(),
+ wrapper_class=structlog.stdlib.BoundLogger,
+ cache_logger_on_first_use=cache_on_use,
+ )
# Mark first line of log
log = structlog.get_logger()
- log.info("first-line")
+ log.info("first-log-line, logging level %d" % logging.root.level)
return log
-def update_logging(instance_id, vcore_id):
+def update_logging(instance_id, vcore_id, cache_on_use=True):
"""
Add the vcore id to the structured logger
:param vcore_id: The assigned vcore id
- :return: structure logger
+ :return: structured logger
"""
- def add_exc_info_flag_for_exception(_, name, event_dict):
- if name == 'exception':
- event_dict['exc_info'] = True
- return event_dict
def add_instance_id(_, __, event_dict):
event_dict['instance_id'] = instance_id
@@ -116,15 +77,22 @@
event_dict['vcore_id'] = vcore_id
return event_dict
- processors = [
- add_exc_info_flag_for_exception,
- structlog.processors.StackInfoRenderer(),
- structlog.processors.format_exc_info,
- add_instance_id,
- add_vcore_id,
- StructuredLogRenderer(),
- ]
- structlog.configure(processors=processors)
+ structlog.configure(
+ processors=[
+ structlog.stdlib.filter_by_level,
+ structlog.stdlib.PositionalArgumentsFormatter(),
+ structlog.processors.StackInfoRenderer(),
+ structlog.processors.format_exc_info,
+ add_instance_id,
+ add_vcore_id,
+ structlog.processors.UnicodeEncoder(),
+ structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+ ],
+ context_class=dict,
+ logger_factory=structlog.stdlib.LoggerFactory(),
+ wrapper_class=structlog.stdlib.BoundLogger,
+ cache_logger_on_first_use=cache_on_use,
+ )
# Mark first line of log
log = structlog.get_logger()