Skip to content

Debug logs duplication due to incorrect configuration #3944

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
nkhitrov opened this issue Jan 18, 2025 · 4 comments · Fixed by #4133
Open

Debug logs duplication due to incorrect configuration #3944

nkhitrov opened this issue Jan 18, 2025 · 4 comments · Fixed by #4133

Comments

@nkhitrov
Copy link

nkhitrov commented Jan 18, 2025

How do you use Sentry?

Self-hosted/on-premise

Version

2.19.2

Steps to Reproduce

Sentry duplicates log records when you set debug mode via sentry_sdk.init() and configure handler in root logger only.

In my project I use structlog so full code example with it

import logging
import sys

import structlog

LOG_LEVEL = logging.DEBUG


def remove_processors_meta(
    _,
    __,
    event_dict,
):
    del event_dict["_record"]
    del event_dict["_from_structlog"]
    event_dict.pop("positional_args", None)
    return event_dict


structlog.configure_once(
    processors=[
        structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
    ],
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)
formatter = structlog.stdlib.ProcessorFormatter(
    pass_foreign_args=True,
    processors=[
        structlog.stdlib.add_logger_name,
        structlog.stdlib.add_log_level,
        structlog.processors.TimeStamper(fmt="%Y-%m-%d %H:%M:%S", utc=True),
        structlog.dev.set_exc_info,
        remove_processors_meta,
        structlog.dev.ConsoleRenderer(
            event_key="message",
            exception_formatter=structlog.dev.better_traceback,
        ),
    ],
)

handler = logging.StreamHandler(stream=sys.stdout)
handler.setFormatter(formatter)

root_logger = logging.getLogger()
root_logger.addHandler(handler)
root_logger.setLevel(LOG_LEVEL)


l = logging.getLogger(__name__)
l.info("test1", extra={"extra": "one"})

import sentry_sdk  # must be after configuration of logging and structlog
from sentry_sdk.utils import logger

sentry_sdk.init("https://123@localhost/1", debug=True)

Expected Result

Sentry does not write log records via own stream handler and use parent (root) logger configuration

Output:

2025-01-18 06:44:33 [info     ] [__main__] event=test1
2025-01-18 06:44:33 [debug    ] [sentry_sdk.errors] event=Setting up integrations (with default = True)
2025-01-18 06:44:33 [debug    ] [sentry_sdk.errors] event=Did not import default integration sentry_sdk.integrations.anthropic.AnthropicIntegration: Anthropic not installed
Image

Actual Result

Output:

 [sentry] DEBUG: Setting up integrations (with default = True)
2025-01-18 06:11:54 [debug    ] Setting up integrations (with default = True) [sentry_sdk.errors] func_name=setup_integrations module=__init__ pathname=/<...>/.venv/lib/python3.11/site-packages/sentry_sdk/integrations/__init__.py process=69509 process_name=MainProcess thread=8643448640 thread_name=MainThread
Image

Possible fix

In debug.py we should change configuration check and use special logger method to check parent handlers too

from this

def init_debug_support():
    # type: () -> None
    if not logger.handlers:
        configure_logger()

to this

def init_debug_support():
    # type: () -> None

    if not logger.hasHandlers():  # check parent handlers
        configure_logger()
@getsantry getsantry bot moved this to Waiting for: Product Owner in GitHub Issues with 👀 3 Jan 18, 2025
@szokeasaurusrex
Copy link
Member

Good idea @nkhitrov

@sentrivana
Copy link
Contributor

Thanks @nkhitrov for the proposed solution, too -- added it. The fix will be out with the next SDK release, probably next week.

szokeasaurusrex added a commit that referenced this issue Apr 14, 2025
This reverts commit 3793084, which made the SDK consider parent loggers when determining if the Sentry SDK should log debug messages.

However, we should not consider parent loggers, since we only want the SDK to log debug messages when configured to do so via `debug=True` (in `sentry_sdk.init`), the `SENTRY_DEBUG` environment variable, or via a specific logger configuration for `sentry_sdk.errors`. With 3793084, a custom root logger configuration would also cause SDK logs to be emitted.

The issue 3793084 was meant to fix (#3944) appears to have been caused by user error, not a bug in the SDK.

Fixes #4266
@szokeasaurusrex
Copy link
Member

Hi @nkhitrov – just writing to let you know that we are going to revert your proposed fix (#4133) because it caused a bug (#4266) where folks with custom log configurations were unexpectedly getting a bunch of debug logs from the Sentry SDK. The change in behavior was due to #4133, and we realized at that point that we in fact did not want the SDK to consider parent loggers when setting up the SDK logger.

We are going to need to come up with a more robust solution for your use case. I will reopen your issue.

szokeasaurusrex added a commit that referenced this issue Apr 14, 2025
This reverts commit 3793084, which made the SDK consider parent loggers when determining if the Sentry SDK should log debug messages.

However, we should not consider parent loggers, since we only want the SDK to log debug messages when configured to do so via `debug=True` (in `sentry_sdk.init`), the `SENTRY_DEBUG` environment variable, or via a specific logger configuration for `sentry_sdk.errors`. With 3793084, a custom root logger configuration would also cause SDK logs to be emitted.

The issue 3793084 was meant to fix (#3944) appears to have been caused by user error, not a bug in the SDK.

Fixes #4266
@szokeasaurusrex
Copy link
Member

szokeasaurusrex commented Apr 14, 2025

As a workaround after we revert our previous fix, you can either disable debug logs for the Sentry SDK, or if you need the debug logs, you can add these lines after the root_logger configuration:

sentry_sdk_logger = logging.getLogger("sentry_sdk.errors")
sentry_sdk_logger.addHandler(handler)
sentry_sdk_logger.setLevel(LOG_LEVEL)

In either case, you would not set debug=True in sentry_sdk.init; instead, you would manually configure the log handler.

szokeasaurusrex added a commit that referenced this issue Apr 14, 2025
This reverts commit 3793084, which made
the SDK consider parent loggers when determining if the Sentry SDK
should log debug messages.

However, we should not consider parent loggers, since we only want the
SDK to log debug messages when configured to do so via `debug=True` (in
`sentry_sdk.init`), the `SENTRY_DEBUG` environment variable, or via a
specific logger configuration for `sentry_sdk.errors`. With
3793084, a custom root logger
configuration would also cause SDK logs to be emitted.

The issue 3793084 was meant to fix
(#3944) will require a different fix.

Fixes #4266
@antonpirker antonpirker added the Improvement label Apr 24, 2025 — with Linear
@stephanie-anderson stephanie-anderson added the Python SDK label Apr 25, 2025 — with Linear
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Archived in project
Development

Successfully merging a pull request may close this issue.

5 participants