def test_sentry_log_specific_keys_as_tags(mocker, level):
m_capture_event = mocker.patch("structlog_sentry.capture_event")
event_data = {
"level": level,
"event": level + " message",
"info1": "info1",
"required": True,
}
tag_keys = ["info1", "required", "some non existing key"]
sentry_event_data = event_data.copy()
processor = SentryProcessor(level=getattr(logging, level.upper()),
tag_keys=tag_keys)
processor(None, None, event_data)
m_capture_event.assert_called_once_with(
{
"level": level,
"message": event_data["event"],
"extra": sentry_event_data,
"tags": {
k: sentry_event_data[k]
for k in tag_keys if k in sentry_event_data
},
},
hint=None,
)
processor_only_errors = SentryProcessor(level=logging.ERROR)
event_dict = processor_only_errors(None, None, {
"level": level,
"event": level + " message"
})
assert event_dict.get("sentry") != "sent"
def test_sentry_log_all_as_tags(mocker, level):
m_capture_event = mocker.patch("structlog_sentry.capture_event")
event_data = {"level": level, "event": level + " message"}
sentry_event_data = event_data.copy()
processor = SentryProcessor(level=getattr(logging, level.upper()),
tag_keys="__all__")
processor(None, None, event_data)
m_capture_event.assert_called_once_with(
{
"level": level,
"message": event_data["event"],
"extra": sentry_event_data,
"tags": sentry_event_data,
},
hint=None,
)
processor_only_errors = SentryProcessor(level=logging.ERROR)
event_dict = processor_only_errors(None, None, {
"level": level,
"event": level + " message"
})
assert event_dict.get("sentry") != "sent"
def test_sentry_get_logger_name():
event_data = {
"level": "info",
"event": "message",
"logger": "EventLogger",
"_record": MockLogger("RecordLogger"),
}
assert (SentryProcessor._get_logger_name(
logger=None, event_dict=event_data) == "EventLogger")
event_data = {
"level": "info",
"event": "message",
"_record": MockLogger("RecordLogger"),
}
assert (SentryProcessor._get_logger_name(
logger=None, event_dict=event_data) == "RecordLogger")
event_data = {
"level": "info",
"event": "message",
}
assert (SentryProcessor._get_logger_name(
logger=MockLogger("EventLogger"),
event_dict=event_data) == "EventLogger")
def test_sentry_log_all_as_tags(mocker, level):
@mocker.create_autospec
def modify_extra(event, **kwargs):
event["extra"].update({"foo": "bar"})
assert "foo" not in event["tags"]
m_capture_event = mocker.patch("structlog_sentry.capture_event",
modify_extra)
event_data = {"level": level, "event": level + " message"}
sentry_event_data = event_data.copy()
processor = SentryProcessor(level=getattr(logging, level.upper()),
tag_keys="__all__")
processor(None, None, event_data)
m_capture_event.assert_called_once_with(
{
"level": level,
"message": event_data["event"],
"extra": sentry_event_data,
"tags": sentry_event_data,
},
hint=None,
)
processor_only_errors = SentryProcessor(level=logging.ERROR)
event_dict = processor_only_errors(None, None, {
"level": level,
"event": level + " message"
})
assert event_dict.get("sentry") != "sent"
def test_sentry_log_failure(mocker, level):
m_capture_event = mocker.patch("structlog_sentry.capture_event")
mocker.patch(
"structlog_sentry.event_from_exception",
return_value=({
"exception": mocker.sentinel.exception
}, mocker.sentinel.hint),
)
event_data = {"level": level, "event": level + " message"}
sentry_event_data = event_data.copy()
processor = SentryProcessor(level=getattr(logging, level.upper()))
try:
1 / 0
except ZeroDivisionError:
processor(None, None, event_data)
m_capture_event.assert_called_once_with(
{
"level": level,
"message": event_data["event"],
"exception": mocker.sentinel.exception,
"extra": sentry_event_data,
},
hint=mocker.sentinel.hint,
)
def test_sentry_ignore_logger(mocker, level):
m_capture_event = mocker.patch("structlog_sentry.capture_event")
blacklisted_logger = MockLogger("test.blacklisted")
whitelisted_logger = MockLogger("test.whitelisted")
processor = SentryProcessor(
level=getattr(logging, level.upper()),
ignore_loggers=["test.blacklisted"],
verbose=True,
)
event_data = {"level": level, "event": level + " message"}
sentry_event_data = event_data.copy()
blacklisted_logger_event_dict = processor(blacklisted_logger, None,
event_data.copy())
whitelisted_logger_event_dict = processor(whitelisted_logger, None,
event_data.copy())
m_capture_event.assert_called_once_with(
{
"level": level,
"message": event_data["event"],
"extra": sentry_event_data,
},
hint=None,
)
assert blacklisted_logger_event_dict.get("sentry") == "ignored"
assert whitelisted_logger_event_dict.get("sentry") != "ignored"
def test_sentry_log_no_extra(mocker, level):
m_capture_event = mocker.patch("structlog_sentry.capture_event")
event_data = {"level": level, "event": level + " message"}
processor = SentryProcessor(level=getattr(logging, level.upper()),
as_extra=False)
processor(None, None, event_data)
m_capture_event.assert_called_once_with(
{
"level": level,
"message": event_data["event"]
}, hint=None)
processor_only_errors = SentryProcessor(level=logging.ERROR)
event_dict = processor_only_errors(None, None, {
"level": level,
"event": level + " message"
})
assert event_dict.get("sentry") != "sent"
def entry_point():
"""Basic entrypoint for cortex subcommands"""
dataset_cache.set_pickle_cache_dir()
sentry_sdk.init(os.getenv("SENTRY_DSN"))
structlog.configure(
processors=[
structlog.stdlib.add_log_level, # required before SentryProcessor()
# sentry_sdk creates events for level >= ERROR and keeps level >= INFO as breadcrumbs.
SentryProcessor(level=logging.INFO),
structlog.processors.TimeStamper(fmt="iso"),
structlog.dev.ConsoleRenderer(),
]
)
def entry_point(ctx): # pylint: disable=no-value-for-parameter
"""Entry point for covid-data-model CLI."""
with sentry_sdk.configure_scope() as scope:
scope.set_tag("command", ctx.invoked_subcommand)
# changes applied to scope remain after scope exits. See
# https://github.com/getsentry/sentry-python/issues/184
structlog.configure(processors=[
structlog.stdlib.add_log_level, # required before SentryProcessor()
# sentry_sdk creates events for level >= ERROR and keeps level >= INFO as breadcrumbs.
SentryProcessor(level=logging.INFO),
structlog.processors.TimeStamper(fmt="iso"),
structlog.dev.ConsoleRenderer(),
])
def test_sentry_log_leave_exc_info_untouched(mocker):
"""Make sure exc_info remains in event_data at the end of the processor.
The structlog built-in format_exc_info processor pops the key and formats
it. Using SentryProcessor, and format_exc_info wasn't possible before,
because the latter one didn't have an exc_info to work with.
https://github.com/kiwicom/structlog-sentry/issues/16
"""
mocker.patch("structlog_sentry.capture_event")
event_data = {"level": "warning", "event": "some.event", "exc_info": True}
processor = SentryProcessor()
try:
1 / 0
except ZeroDivisionError:
processor(None, None, event_data)
assert "exc_info" in event_data
def test_sentry_log_failure(mocker, level):
"""Make sure that events without exc_info=True will have no
'exception' information after processing"""
m_capture_event = mocker.patch("structlog_sentry.capture_event")
event_data = {"level": level, "event": level + " message"}
sentry_event_data = event_data.copy()
processor = SentryProcessor(level=getattr(logging, level.upper()))
try:
1 / 0
except ZeroDivisionError:
processor(None, None, event_data)
m_capture_event.assert_called_once_with(
{
"level": level,
"message": event_data["event"],
"extra": sentry_event_data
},
hint=None,
)
def test_sentry_log_failure_exc_info_true(mocker, level):
"""Make sure sentry_sdk.utils.exc_info_from_error doesn't raise ValueError
Because it can't introspect exc_info.
Bug triggered when logger.error(..., exc_info=True) or logger.exception(...)
are used.
"""
m_capture_event = mocker.patch("structlog_sentry.capture_event")
event_data = {
"level": level,
"event": level + " message",
"exc_info": True
}
processor = SentryProcessor(level=getattr(logging, level.upper()))
try:
1 / 0
except ZeroDivisionError:
processor(None, None, event_data)
assert m_capture_event.call_count == 1
_, kwargs = m_capture_event.call_args
assert kwargs["hint"]["exc_info"][0] == ZeroDivisionError
def test_sentry_add_logger_name(mocker, logger):
m_capture_event = mocker.patch("structlog_sentry.capture_event")
event_data = {"level": "warning", "event": "some.event"}
if logger is not absent:
event_data["logger"] = logger
processor = SentryProcessor(as_extra=False)
processor(None, None, event_data)
if logger is absent:
m_capture_event.assert_called_once_with(
{
"level": "warning",
"message": "some.event"
}, hint=None)
else:
m_capture_event.assert_called_once_with(
{
"level": "warning",
"message": "some.event",
"logger": logger
},
hint=None)
def setup_logging(
debug: bool = False,
capture_stdout: bool = False,
json_logging: bool = False,
*,
sentry: bool = False,
_test_logging: bool = False,
) -> None:
import logging
import logging.config
import structlog
import twisted
from twisted.logger import LogLevel
# Mappings to Python's logging module
twisted_to_logging_level = {
LogLevel.debug: logging.DEBUG,
LogLevel.info: logging.INFO,
LogLevel.warn: logging.WARNING,
LogLevel.error: logging.ERROR,
LogLevel.critical: logging.CRITICAL,
}
# common timestamper for structlog loggers and foreign (stdlib and twisted) loggers
timestamper = structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S")
# processors for foreign loggers
pre_chain = [
structlog.stdlib.add_log_level,
structlog.stdlib.add_logger_name,
timestamper,
]
# docs at http://www.structlog.org/en/stable/api.html#structlog.dev.ConsoleRenderer
class ConsoleRenderer(structlog.dev.ConsoleRenderer):
def __call__(self, _, __, event_dict):
from io import StringIO
from structlog.dev import _pad
sio = StringIO()
ts = event_dict.pop('timestamp', None)
if ts is not None:
sio.write(
# can be a number if timestamp is UNIXy
self._styles.timestamp + str(ts) + self._styles.reset +
' ')
level = event_dict.pop('level', None)
if level is not None:
sio.write('[' + self._level_to_color[level] +
_pad(level, self._longest_level) +
self._styles.reset + '] ')
logger_name = event_dict.pop('logger', None)
if logger_name is not None:
sio.write('[' + self._styles.logger_name +
self._styles.bright + logger_name +
self._styles.reset + '] ')
event = str(event_dict.pop('event'))
if event_dict:
event = _pad(event, self._pad_event) + self._styles.reset + ' '
else:
event += self._styles.reset
sio.write(self._styles.bright + event)
stack = event_dict.pop('stack', None)
exc = event_dict.pop('exception', None)
sio.write(' '.join(self._styles.kv_key + key + self._styles.reset +
'=' + self._styles.kv_value +
self._repr(event_dict[key]) + self._styles.reset
for key in sorted(event_dict.keys())))
if stack is not None:
sio.write('\n' + stack)
if exc is not None:
sio.write('\n\n' + '=' * 79 + '\n')
if exc is not None:
sio.write('\n' + exc)
return sio.getvalue()
@staticmethod
def get_default_level_styles(colors=True):
import colorama
if not colors:
return structlog.dev.ConsoleRenderer.get_default_level_styles(
False)
return {
'critical': colorama.Style.BRIGHT + colorama.Fore.RED,
'exception': colorama.Fore.RED,
'error': colorama.Fore.RED,
'warn': colorama.Fore.YELLOW,
'warning': colorama.Fore.YELLOW,
'info': colorama.Fore.GREEN,
'debug': colorama.Style.BRIGHT + colorama.Fore.CYAN,
'notset': colorama.Back.RED,
}
def _repr(self, val):
if isinstance(val, datetime):
return str(val)
else:
return super()._repr(val)
if json_logging:
handlers = ['json']
else:
handlers = ['pretty']
# See: https://docs.python.org/3/library/logging.config.html#configuration-dictionary-schema
logging.config.dictConfig({
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'plain': {
'()': structlog.stdlib.ProcessorFormatter,
'processor': ConsoleRenderer(colors=False),
'foreign_pre_chain': pre_chain,
},
'colored': {
'()': structlog.stdlib.ProcessorFormatter,
'processor': ConsoleRenderer(colors=True),
'foreign_pre_chain': pre_chain,
},
'json': {
'()': structlog.stdlib.ProcessorFormatter,
'processor': structlog.processors.JSONRenderer(),
'foreign_pre_chain': pre_chain,
},
},
'handlers': {
'pretty': {
'level': 'DEBUG',
'class': 'logging.StreamHandler',
'formatter': 'colored',
},
'json': {
'level': 'DEBUG',
'class': 'logging.StreamHandler',
'formatter': 'json',
},
# 'file': {
# 'level': 'DEBUG',
# 'class': 'logging.handlers.WatchedFileHandler',
# 'filename': 'test.log',
# 'formatter': 'plain',
# },
},
'loggers': {
# set twisted verbosity one level lower than hathor's
'twisted': {
'handlers': handlers,
'level': 'INFO' if debug else 'WARN',
'propagate': False,
},
'': {
'handlers': handlers,
'level': 'DEBUG' if debug else 'INFO',
},
}
})
def kwargs_formatter(_, __, event_dict):
if event_dict and event_dict.get('event') and isinstance(
event_dict['event'], str):
event_dict['event'] = event_dict['event'].format(**event_dict)
return event_dict
processors: List[Any] = [
structlog.stdlib.filter_by_level,
structlog.stdlib.add_logger_name,
structlog.stdlib.add_log_level,
]
if sentry:
from structlog_sentry import SentryProcessor
processors.append(SentryProcessor(level=logging.ERROR))
processors.extend([
structlog.stdlib.PositionalArgumentsFormatter(),
kwargs_formatter,
timestamper,
structlog.processors.StackInfoRenderer(),
structlog.processors.format_exc_info,
structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
])
structlog.configure(
processors=processors,
context_class=OrderedDict,
logger_factory=structlog.stdlib.LoggerFactory(),
wrapper_class=structlog.stdlib.BoundLogger,
cache_logger_on_first_use=True,
)
twisted_logger = structlog.get_logger('twisted')
def twisted_structlog_observer(event):
try:
level = twisted_to_logging_level.get(event.get('log_level'),
logging.INFO)
kwargs = {}
msg = ''
if not msg and event.get('log_format', None):
msg = event['log_format'].format(**event)
if not msg and event.get('format', None):
msg = event['format'] % event
failure = event.get('log_failure')
if failure is not None:
kwargs['exc_info'] = (failure.type, failure.value,
failure.getTracebackObject())
twisted_logger.log(level, msg, **kwargs)
except Exception as e:
print('error when logging event', e)
for k, v in event.items():
print(k, v)
# start logging to std logger so structlog can catch it
twisted.python.log.startLoggingWithObserver(twisted_structlog_observer,
setStdout=capture_stdout)
if _test_logging:
logger = structlog.get_logger()
logger.debug('Test: debug.')
logger.info('Test: info.')
logger.warning('Test: warning.')
logger.error('Test error.')
logger.critical('Test: critical.')
def configure_logging(command: Optional[str] = None):
"""Configure stdlib logging and structlog, and if SENTRY_DSN is set, Sentry.
Parameters:
command: a command name added to the Sentry events.
"""
# First structlog is configured to send errors to Sentry and use stdlib for console logging. If we start
# getting duplicate logs from structlog I'm guessing stdlib is also logging them so remove SentryProcessor.
# Based on https://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging
structlog.configure(
context_class=dict,
wrapper_class=structlog.stdlib.BoundLogger,
processors=[
structlog.stdlib.
add_log_level, # required before SentryProcessor()
# sentry_sdk creates events for level >= ERROR. Getting breadcrumbs from structlog isn't supported
# without a lot of custom work. See https://github.com/kiwicom/structlog-sentry/issues/25
SentryProcessor(level=logging.ERROR),
structlog.processors.TimeStamper(fmt="iso"),
structlog.processors.StackInfoRenderer(),
structlog.processors.format_exc_info,
# It is important that wrap_for_formatter is the last processor. It converts the processed
# event dict to something that the ProcessorFormatter (the logging.Formatter passed to
# setFormatter) understands.
structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
],
logger_factory=structlog.stdlib.LoggerFactory(),
cache_logger_on_first_use=True,
)
# Second, configure stdlib logging to format structlog events and any other parameters we want to set.
formatter = structlog.stdlib.ProcessorFormatter(
# TODO(tom) fix https://github.com/hynek/structlog/issues/166 so keys appear in added order
processor=structlog.dev.ConsoleRenderer(),
foreign_pre_chain=[
structlog.stdlib.add_logger_name,
structlog.processors.TimeStamper(fmt="iso"),
],
)
handler = logging.StreamHandler()
handler.setFormatter(formatter)
root_logger = logging.getLogger()
root_logger.addHandler(handler)
root_logger.setLevel(logging.INFO)
# Finally initialize sentry_sdk.
sentry_dsn = os.getenv("SENTRY_DSN")
sentry_environment = None
if SENTRY_ENVIRONMENT_ENV in os.environ:
sentry_environment = Environment(os.getenv(SENTRY_ENVIRONMENT_ENV))
if sentry_dsn:
sentry_sdk.init(sentry_dsn, environment=sentry_environment)
if command:
with sentry_sdk.configure_scope() as scope:
scope.set_tag("command", command)
def test_sentry_sent():
processor = SentryProcessor()
event_dict = processor(None, None, {"level": "error"})
assert event_dict.get("sentry") == "sent"
def test_sentry_skip():
processor = SentryProcessor(verbose=True)
event_dict = processor(None, None, {"sentry_skip": True, "level": "error"})
assert event_dict.get("sentry") == "skipped"
def test_sentry_disabled():
processor = SentryProcessor(active=False)
event_dict = processor(None, None, {"level": "error"})
assert event_dict.get("sentry") != "sent"
def test_sentry_skip():
processor = SentryProcessor()
event_dict = processor(None, None, {"sentry_skip": True, "level": "error"})
assert event_dict.get("sentry") != "sent"
