Log message formatting options

[techdragon]

The raven client had a defined log handler which let you use python's built in logging configuration mechanisms to control how log messages looked when they were passed to sentry, however the new python-sdk does not appear to have any equivalent option. I have a number of apps where I have log messages managed by structlog, where structlog hooks into python's logging and formatts everything nicely with pretty readable colours, nicely formatted timestamps, before it gets sent to stdout, however the combination of how python-sdk hooks into logging, and the formatting of these messages means that the new sentry-sdk logging integration/handling makes an absolute mess of things producing unhelpful results in sentry.io like dozens of variations of [2m2019-01-03T07:16:00.573607Z[0m [[31m[1merror [0m] [1mcan_send_message is Fals... each with one recorded error event, instead of a single can_send_message is False with the correct count of error events.

What is the mechanism for the sentry-sdk to work with python's logging formatters and libraries such as structlog?

[untitaker]

sentry_sdk has two handler classes sentry_sdk.integrations.BreadcrumbHandler and sentry_sdk.integrations.EventHandler. You can use those directly while disabling the logging integration by using this:

sentry_sdk.init(integrations=sentry_sdk.integrations.logging.LoggingIntegration(event_level=None, level=None))

I would like to understand if this fixes your issue or if there's a minor thing Raven does that makes it somehow work with structlog. I don't understand how sentry-sdk gets ahold of the formatted message at all. It only accesses record.msg and record.args

[techdragon]

Your suggestion would "remove" the issue, but that is not really fixing it, and would prevent me from having sentry capture error related log messages from 3rd party libraries.

The difference (at least as far as i can tell) between raven and the new sentry-sdk, is the ability to configure what gets passed to sentry using standard python logging configuration. The logging.config.dictConfig example shown on this page https://docs.sentry.io/clients/python/integrations/logging/ already shows the use of a different log message formatter. As you can see on the section in structlogs documentation on using structlog as a log message formatter, http://www.structlog.org/en/stable/standard-library.html#rendering-using-structlog-based-formatters-within-logging this is all done with the normal python log message tools. Structlog and Raven each get passed a copy of the message as registered handlers, and do their respective things with log messages separately.

[untitaker]

Your suggestion would "remove" the issue, but that is not really fixing it, and would prevent me from having sentry capture error related log messages from 3rd party libraries.

I don't see how. Using the code I provided and explicitly registering an instance of EventHandler and BreadcrumbHandler at the root logger (logging.getLogger()) replicates the raven behavior exactly, because that's exactly what setup_logging in raven does

It will take me a while to investigate this, but I just don't see how formatters are related to this at all. We capture the record before it ever gets formatted.

[keramblock]

Have same issue

[untitaker]

I don't understand the issue. Could somebody make a demo app and describe expected behavior? I think that's the easiest way to communicate this at this point.

[md1023]

You don't want your structured logs in Sentry, you'll get overwhelmed. You want unhandled exceptions there. Adjust your Sentry to send log events as sentry breadcrumbs instead of sentry events by setting event_level=None.

[keramblock]

This is how sentry is integrated right now:
sentry_sdk.init( SENTRY_DSN )
This is how error looks like in console:

`
2019-03-22T13:21:56 [error ] Got an error, helm command:
['helm', 'upgrade', 'ds-u-auth-mk', '--install', '--wait', '--force', '--recreate-pods', '--timeout', '900', '--debug', '/opt/helm/pr', '-f', '/tmp/tmpvwu39xz5'], helm output:
[debug] Created tunnel using local port: '46359'

[debug] SERVER: "127.0.0.1:46359"

Release "ds-u-auth-mk" does not exist. Installing it now.
[debug] CHART PATH: /opt/helm/pr

E0322 13:21:56.338264 476 portforward.go:224] lost connection to pod
Error: transport is closing

[clients.helm]
`

In attach you could see how my sentry currently looks like in this project.

[keramblock]

So the first problem - its hard to understand this text.
Second problem - every time you getting an error - sentry thinks, that it is a new one, even if it not.

Seems, that I am doing it wrong, but for now I don't understanding where exactly I mistaken.

[odannyc]

I have the same issue.
I have structlog outputting JSON formatted logs (for kibana/elasticsearch to understand), unfortunately now every event/breadcrumb in Sentry is just a message with a stringified JSON blob. The solution I think for this is pretty simple... Before sending the event to Sentry, I want to try and deserialize the JSON and set the correct fields in the Sentry event/breadcrumbs...
Is this possible with this library?

[untitaker]

@odannyc I am planning to look at this soon. Ideally it should work without the user doing anything

[odannyc]

@untitaker
Thank you!

I actually got it sort of working now. Before I was using the structlog format... Which basically has a event key which contains the message. Now I changed it so [json-python-logger](https://github.com/madzak/python-json-logger) takes care of outputting the json - which has the message in a message key. This now displays correctly in Sentry BUT doesn't display the exception stack trace. For example:

{
  "message": "something bad happened",
  "request_id": "asdf",
  "exception": "[an exception stacktrace in here]"
}

The sentry python lib will not look at exception key in this case and format it correctly in Sentry

[untitaker]

I did some investigation on this now and I still don't see how Raven could've ever worked better than sentry-sdk.

Processors concept conflates too much responsibilities

The fundamental problem I see here is that structlog's processors are not clearly separated into modifying semantics of the event dictionary, vs modifying how the event is printed.

• A trivial example is PositionalArgumentsFormatter, whose usage already breaks Sentry's grouping of events into issues. A part of our grouping heuristic for events without exceptions relies on log messages not having their arguments formatted, because we group events by message template.

• Another example is format_exc_info, which stringifies exception info into the event dict. So by the time the log record reaches stdlib logging, most of the data is already stringified and therefore unusuable for Sentry.

structlog event dict has no schema

I also think structlog's flexibility makes it at hard for us to provide a one-size-fits-all solution here. While it does allow you to log JSON, the JSON is less "structured" than the a stdlib logging record: A logging.LogRecord has documented fields such as exc_info while structlog only has a convention of using the exception key which might or might not be used depending on which processors are enabled.

Proposal

Instead of adding workarounds to our logging integration to unscramble/decode the stringified JSON structlog sends into stdlib logging (that is, if it even is JSON) I would propose that the SDK should hook into structlog itself. For a start we should export a processor that extracts data from the event dict and just make the SDK user set up the processor themselves. This also means that a logger name used for structlog records has to be explicitly ignored to not log any stdlib logging records into Sentry, as otherwise we would get an issue for the structlog record and the stdlib logging reord.

Attached is the experimental code I used to test this idea. I'd be grateful for any feedback especially from @techdragon who seems to have a more comprehensible understanding of structlog and how Raven dealt with its output. I hope it's at least useful to somebody who wants basic exceptions working in Sentry:

Click to expand

import sys
import logging
import structlog
import sentry_sdk
from sentry_sdk.utils import event_from_exception
from sentry_sdk.integrations.logging import ignore_logger
import pprint

# Extract sentry event from structlog event
def structlog_sentry_processor(logger, method_name, d):
    event = {}
    hint = None

    if method_name == 'exception' or 'exception' in d:
        event, hint = event_from_exception(sys.exc_info())

    if 'exc_info' in d:
        exc_info = d['exc_info']
        if exc_info is True:
            exc_info = sys.exc_info()
        event, hint = event_from_exception(exc_info)

    event.update({
        "logentry": {
            "message": d['event'],
            "params": d.get('positional_args')
        },
        "level": method_name,
        'extra': {"structlog-event": d}
    })
    sentry_sdk.capture_event(event, hint=hint)

    return d

structlog.configure(
    processors=[
        structlog_sentry_processor,
        structlog.stdlib.PositionalArgumentsFormatter(),
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    logger_factory=structlog.stdlib.LoggerFactory(),
)

# Ignore structlog stdlib logger because we already extracted the event
ignore_logger("structlog_logger")

formatter = structlog.stdlib.ProcessorFormatter(
    processor=structlog.dev.ConsoleRenderer(),
)

handler = logging.StreamHandler()
handler.setFormatter(formatter)
root_logger = logging.getLogger()
root_logger.addHandler(handler)
root_logger.setLevel(logging.INFO)

sentry_sdk.init(transport=lambda e: pprint.pprint(e))

log = structlog.get_logger("structlog_logger")

try:
    1/0
except:
    log.exception("hello %s %s", positional_args=("argument1", "argument2"), foo='bar')

[techdragon]

@untitaker I think I could probably have been clearer in how I explained the whole Sentry SDK vs Raven thing. Fundamentally the discrepancy was one of documented functionality. Raven logging worked by adding the log handler into pythons built in logging system. The Sentry SDK tries to do this automatically which when combined with structlog results in failure out of the box, producing Sentry events just like in the screenshot posted by @keramblock. I eventually worked out how to make the Sentry SDK subordinate to Python's default logging toolchain, but while I still feel it is a "sub-optimal" solution, it's working in production, so it is good enough to do its job. I'll explain my solution here for comparison purposes.

Note: I've pieced this together from a few places around the web, I know the core came from @psviderski, but the rest I've forgotten since this was a bit of a rush job, so if anyone else recognises their code in this, you have my thanks! ( as do you @psviderski ! )

First thing is to ensure that the Sentry SDK doesn't use its own logging integration. (This example is from our celery worker setup, so CeleryIntegration has also been included.)

sentry_sdk.init(
    SENTRY_DSN,
    environment=ENVIRONMENT,
    integrations=[
        CeleryIntegration(), 
        LoggingIntegration(event_level=None, level=None)
    ]
)

That was the easy part, now for how to setup the logging stuff...
I ended up creating a custom adapter to parse structlog's event_dict, and to push the content over into stdlib logging's extra kwarg and a matching processor to extract the extra and push it into the event_dict

LOG_RECORD_ATTRIBUTES = {
    'args', 'asctime', 'created', 'exc_info', 'exc_text', 'filename',
    'funcName', 'levelname', 'levelno', 'lineno', 'message', 'module',
    'msecs', 'msg', 'name', 'pathname', 'process', 'processName',
    'relativeCreated', 'stack_info', 'thread', 'threadName',
}
BASIC_TYPES = (str, bool, int, float, type(None))

def structlog_to_stdlib_adapter(logger, method_name, event_dict):
    """
    Pass the `event_dict` as `extra` keyword argument to the standard logger.
    """
    exclude_keys = ['logger', 'level']
    event = event_dict.pop('event', "")
    for key in exclude_keys:
        event_dict.pop(key, None)
    # Rename keys that conflict with the reserved LogRecord attributes
    conflicting_keys = set(event_dict) & LOG_RECORD_ATTRIBUTES
    for key in conflicting_keys:
        event_dict[key + '_'] = event_dict.pop(key)
    # Replace extra values of non-basic types with their string representation to make
    # sure they will become JSON-serializable (essential for logstash logging handler).
    event_dict = {k: v if isinstance(v, BASIC_TYPES) else repr(v)
                  for k, v in event_dict.items()}
    kwargs = {
        'extra': event_dict,
        'exc_info': 'exception' in event_dict,
    }
    return (event,), kwargs


def extract_stdlib_extra(logger, method_name, event_dict):
    """
    Extract the `extra` key-values from the standard logger record
    and populate the `event_dict` with them.
    """
    record_extra = {k: v for k, v in vars(event_dict['_record']).items()
                    if k not in LOG_RECORD_ATTRIBUTES}
    event_dict.update(record_extra)
    return event_dict

Now I have these tools to work with, I have to configure Structlog, Standard Library logging, and Sentry. This largely aligns with the documentation provided by structlog, but with modifications to use the processor functions and to fit in the Sentry SDK.

I build a default_processor list and a processor list for the logs that will be pushed to std_out via python's built in logging system.

default_processors = [
    structlog.stdlib.add_logger_name,
    structlog.stdlib.add_log_level,
    structlog.stdlib.PositionalArgumentsFormatter(),
    structlog.processors.TimeStamper(fmt='iso'),
    structlog.processors.StackInfoRenderer(),
    structlog.processors.format_exc_info,
    structlog_to_stdlib_adapter,
]

console_log_processor_chain = [
    structlog.stdlib.add_logger_name,
    structlog.stdlib.add_log_level,
    structlog.stdlib.PositionalArgumentsFormatter(),
    structlog.processors.TimeStamper(fmt='iso'),
    structlog.processors.StackInfoRenderer(),
    structlog.processors.format_exc_info,
    extract_stdlib_extra,
]

I use the default_processor list when configuring structlog's defaults.

structlog.configure(
    # Default is context_class=collections.OrderedDict, but dict is ordered in Python > 3.6
    context_class=dict,
    processors=default_processors,
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,  # for better performance.
)

And finally I set up the standard library logging to tie everything together.

logging_configuration_dictionary = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "standard_output": {
            "()": structlog.stdlib.ProcessorFormatter,
            "processor": structlog.dev.ConsoleRenderer(colors=True),
            "foreign_pre_chain": console_log_processor_chain,
        }
    },
    "handlers": {
        "console": {
            "level": "DEBUG",
            "class": "logging.StreamHandler",
            "formatter": "standard_output",
        },
        'sentry': {
            'level': 'ERROR',
            'class': 'sentry_sdk.integrations.logging.EventHandler',
        }
    },
    "loggers": {
        "": {
            "handlers": [
                "console"
            ],
            "level": "DEBUG",
            "propagate": True,
        },
    }
}

# This ensures that we only add the Sentry SDK handler as a
# log handlers when we actually have a Sentry configuration.
# This handles turning off sentry for local dev, etc.
if SENTRY_DSN:
    logging_configuration_dictionary["loggers"][""]["handlers"].append("sentry")

logging.config.dictConfig(logging_configuration_dictionary)

The end result is that A log message will go through roughly the following transformations as a log event is processed.

Structlog Logging Call  
    \|/
Standard Lib Compatible Form -> Std lib logging calls Sentry via sentry_sdk.integrations.logging.EventHandler
    \|/
Std lib logging calls Structlog Formatter structlog.stdlib.ProcessorFormatter
    \|/
Structlog Formatter re-parses back into structlog format 
    \|/
Normal Structlog + Stdlib logging continues here.

@untitaker I think this all falls squarely into the "adding workarounds. I didn't have to decode the JSON, but its not far from it haha.

Instead of adding workarounds to our logging integration to unscramble/decode the stringified JSON structlog sends into stdlib logging (that is, if it even is JSON) I would propose that the SDK should hook into structlog itself.

I've gone over the example at the end of the post and while it does get the basics working, it doesn't really cover as much as my workaround does. I was forced down this road in part due to our already complex logging setup built on top of how flexible structlog is. You rightly highlighted this flexibility as one of the issues @untitaker and I think perhaps the best way to solve it is to lean into the flexibility by not trying to handle it automatically like it does for standard library logging.

A structlog event processor similar to your example, with some more configuration options similar to the existing logging integration settings, that could decide if the log event from structlog should be captured to sentry (eg: log level > error, etc) and just handle it mostly automatically + documentation specifying that you should turn off the built in logging integration and use the sentry processor if you use structlog.

An alternative would be a processor function that does the event_dict mapping, the remaining formatting stuff, dumps anything it cant handle into the extra, and then just passes it to sentry if the event_dict contains send_to_sentry: True, documents this, and leaves it up to users to build a log processor that decides which messages they want to send to sentry. (the sentry log processor can remove send_to_sentry from the event_dict before passing it on to keep things clean.)

Any thoughts on these approaches @untitaker ?