Monitoring and centralized logging integration strategy

[rudyryk]

I'm trying switching to Loguru for my newer projects and I'm wondering, what is recommended approach to perform integrations with services like Sentry, etc.?

For example, Sentry has built-in standard logging library hooks. But it won't work with the standard logging intercepted by Loguru.

Should we create custom sink? That could be tricky, and actually, could introduce extra bugs, so it needs to have solid design and bunch of tests. Application broken because of bugs monitoring a is kind of "fun but not fun".

[rudyryk]

For Sentry integration I came up to such code:

import sys
from loguru import logger
import logging
from sentry_sdk.integrations.logging import LoggingIntegration, EventHandler
SENTRY_DSN = '...'
logger.remove()
sentry_sdk.init(
    SENTRY_DSN,
    integrations=[LoggingIntegration(level=None, event_level=None)],
)
logger.add(sys.stderr, level='INFO')
logger.add(EventHandler(level=logging.WARNING))

# + InterceptHandler from README.md
# ...
logging.basicConfig(handlers=[InterceptHandler()], level=0)

Will test how it works out.

[Delgan]

Hi @rudyryk.

As you figured out, I think simply adding a Sentry EventHandler or BreadcrumbHandler to the Loguru logger should work fine.

Combining this with the InterceptHandler() ensure that logs emitted the standard logging library will be captured too.

Please, let me know if this does not work as expected.

[rudyryk]

@Delgan unfortunately, I faced weird issue, I got endless messages sent to the Sentry server:

...
2020-10-08 21:34:56.524 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:56.634 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:56.704 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:56.817 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:56.870 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:56.977 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:57.028 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:57.141 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:57.193 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:57.297 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:57.363 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:57.473 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:57.539 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:57.645 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
2020-10-08 21:34:57.706 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41
^C2020-10-08 21:34:57.803 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41

An example of message received:

2020-10-08 21:42:57.985 | DEBUG    | sentry_sdk.integrations.logging:sentry_patched_callhandlers:83 - https://sentry.mysite.org:443 "POST /api/9/store/ HTTP/1.1" 200 41

Seems like some cyclic logging behaviour.

[Delgan]

Sorry, I'm not a Sentry user and consequently I'm not able to reproduce your problem. :(

Would this be possible that events emitted by the EventHandler() would somehow be captured by Sentry which would generate new logs causing EventHandler() to emit new events and so on? I have no clue about what could be causing the behavior you're experiencing. :confused:

[rudyryk]

Would this be possible that events emitted by the EventHandler() would somehow be captured by Sentry which would generate new logs causing EventHandler() to emit new events and so on?

My guess is that's what happening exactly, but I didn't have chance to deep dive. Sentry is a major player in monitoring and crashes tracking in Python world, I think it's crucial to have solid workflow to make them play well with each other.

[Delgan]

Indeed, it is very important that loguru and sentry can work together. From what I've seen, several people use both of them without any problem, though.

If you have any idea how to create a minimum reproducible example of the issue you're facing, please let me know.

I have some doubts about the use of sentry_sdk.init() in your example. I'm not sure, but I'm thinking that it might be the one that causes conflicts with other handlers added manually.

[rudyryk]

@Delgan Yes, it's possible that some other hooks are also involved, I'll try to provide basic reproducible example.

[Soures888]

@rudyryk Have you found a solution?

[Delgan]

Hi @Soures888. Did you encounter the same issue? Are you able to create a minimal reproducible example?

[TheZavitaev]

Hi guys! Just use this solution: https://github.com/getsentry/sentry-python/issues/653#issuecomment-788854865

[kbakk]

Hi,

I'm seeing some issues with using Sentry and Loguru. Here's a reproducer:

t.py

import logging
import os
import sys
from loguru import logger
import sentry_sdk


class InterceptHandler(logging.Handler):
    def emit(self, record):
        # Get corresponding Loguru level if it exists
        try:
            level = logger.level(record.levelname).name
        except (ValueError, TypeError):
            level = record.levelno

        # Find caller from where originated the logged message
        frame, depth = logging.currentframe(), 2
        while frame.f_code.co_filename == logging.__file__:
            frame = frame.f_back
            depth += 1

        logger.opt(depth=depth, exception=record.exc_info).log(
            level, record.getMessage()
        )


logging.basicConfig(handlers=[InterceptHandler()], level=0)
level_per_module = {"": "DEBUG", "sentry_sdk": "INFO"}
logger.remove()
logger.add(
    sys.stderr,
    filter=level_per_module,
    diagnose=False,
    colorize=True,
    format="{level: <8} | {name}:{line} ({module}) | <level>{message}</level>",
    level="DEBUG",
)
sentry_sdk.init(
    os.getenv("SENTRY_SDK")
)

std_logger = logging.getLogger("std_logger")
std_logger.info("Test info msg")
std_logger.debug("Test debug msg - not shown")

logger.debug("Test msg")

$ python t.py
INFO     | sentry_sdk.integrations.logging:86 (logging) | Test info msg
DEBUG    | __main__:45 (t) | Test msg

If I comment out the sentry_sdk.init statement, I'll get the expected output:

$ python t.py
INFO     | __main__:42 (t) | Test info msg
DEBUG    | __main__:43 (t) | Test debug msg - not shown
DEBUG    | __main__:45 (t) | Test msg

It looks like the sentry_sdk overwrites some of the data.

[kbakk]

Playing around a bit, I tried changing

         # Find caller from where originated the logged message
         frame, depth = logging.currentframe(), 2
-        while frame.f_code.co_filename == logging.__file__:
+        while (
+            frame.f_code.co_filename == logging.__file__
+            or "sentry_sdk/integrations" in frame.f_code.co_filename
+        ):
             frame = frame.f_back
             depth += 1

It seems to have the desired effect:

$ python t.py
INFO     | __main__:46 (t) | Test info msg
DEBUG    | __main__:47 (t) | Test debug msg - not shown
DEBUG    | __main__:49 (t) | Test msg

This might introduce some other problems, so not sure I can recommend this.

[kbakk]

The above is similar to what @fratambot writes in https://github.com/Delgan/loguru/issues/509

[fratambot]

The above is similar to what @fratambot writes in #509

Hey @kbakk, in the end I managed to integrate nicely loguru and sentry. You can take a look at what I've done here: https://github.com/Delgan/loguru/issues/554#issue-1081197682 I hope it can help you ! :)

[Delgan]

Hey @kbakk. Thanks for the reproducible example. This seems definitely related to how logging is configured by sentry_sdk.init(). I do not know what's happening under the hood, but it somehow breaks the InterceptHandler expectations.

I figured out you could configure Sentry with default_integrations=False to generate the expected logs. This has probably some side effect I'm not aware of, documentation is mentioning two handlers you may need to install manually: Logging | Sentry Documentation.

Hope it might help.

[Delgan]

It seems Sentry now officially supports Loguru: Learn about using Sentry with Loguru.

Consequently, I'm closing this ticket. The integration should be quite straightforward.