Skip to content
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

More lenient handling of loguru message mismatch and better warnings #338

Merged
merged 3 commits into from
Jul 29, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 2 additions & 4 deletions logfire/_internal/config.py
Original file line number Diff line number Diff line change
Expand Up @@ -76,7 +76,7 @@
from .integrations.executors import instrument_executors
from .metrics import ProxyMeterProvider, configure_metrics
from .scrubbing import NOOP_SCRUBBER, BaseScrubber, Scrubber, ScrubbingOptions, ScrubCallback
from .stack_info import get_user_frame_and_stacklevel
from .stack_info import warn_at_user_stacklevel
from .tracer import PendingSpanProcessor, ProxyTracerProvider
from .utils import UnexpectedResponse, ensure_data_dir_exists, get_version, read_toml_file, suppress_instrumentation

Expand Down Expand Up @@ -801,12 +801,10 @@ def get_meter_provider(self) -> ProxyMeterProvider:

def warn_if_not_initialized(self, message: str):
if not self._initialized and not self.ignore_no_config:
_frame, stacklevel = get_user_frame_and_stacklevel()
warnings.warn(
warn_at_user_stacklevel(
f'{message} until `logfire.configure()` has been called. '
f'Set the environment variable LOGFIRE_IGNORE_NO_CONFIG=1 or add ignore_no_config=true in pyproject.toml to suppress this warning.',
category=LogfireNotConfiguredWarning,
stacklevel=stacklevel,
)

@cached_property
Expand Down
6 changes: 2 additions & 4 deletions logfire/_internal/formatter.py
Original file line number Diff line number Diff line change
Expand Up @@ -14,10 +14,10 @@
from typing_extensions import NotRequired, TypedDict

import logfire
from logfire._internal.stack_info import get_user_frame_and_stacklevel

from .constants import ATTRIBUTES_SCRUBBED_KEY, MESSAGE_FORMATTED_VALUE_LENGTH_LIMIT
from .scrubbing import NOOP_SCRUBBER, BaseScrubber, ScrubbedNote
from .stack_info import warn_at_user_stacklevel
from .utils import log_internal_error, truncate_string


Expand Down Expand Up @@ -466,14 +466,12 @@ class FormattingFailedWarning(UserWarning):


def warn_formatting(msg: str):
_frame, stacklevel = get_user_frame_and_stacklevel()
warnings.warn(
warn_at_user_stacklevel(
f'\n'
f' Ensure you are either:\n'
' (1) passing an f-string directly, with inspect_arguments enabled and working, or\n'
' (2) passing a literal `str.format`-style template, not a preformatted string.\n'
' See https://docs.pydantic.dev/logfire/guides/onboarding_checklist/add_manual_tracing/#messages-and-span-names.\n'
f' The problem was: {msg}',
stacklevel=stacklevel,
category=FormattingFailedWarning,
)
6 changes: 6 additions & 0 deletions logfire/_internal/stack_info.py
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@

import inspect
import sys
import warnings
from functools import lru_cache
from pathlib import Path
from types import CodeType, FrameType
Expand Down Expand Up @@ -97,3 +98,8 @@ def is_user_code(code: CodeType) -> bool:
str(Path(code.co_filename).absolute()).startswith(PREFIXES)
or code.co_name in ('<listcomp>', '<dictcomp>', '<setcomp>')
)


def warn_at_user_stacklevel(msg: str, category: type[Warning]):
_frame, stacklevel = get_user_frame_and_stacklevel()
warnings.warn(msg, stacklevel=stacklevel, category=category)
72 changes: 40 additions & 32 deletions logfire/integrations/loguru.py
Original file line number Diff line number Diff line change
Expand Up @@ -3,15 +3,25 @@
from __future__ import annotations

import inspect
import warnings
from logging import LogRecord
from pathlib import Path
from typing import Any

from loguru import logger
import loguru

from .._internal.constants import ATTRIBUTES_LOGGING_ARGS_KEY, ATTRIBUTES_MESSAGE_KEY, ATTRIBUTES_MESSAGE_TEMPLATE_KEY
from .._internal.stack_info import warn_at_user_stacklevel
from .logging import LogfireLoggingHandler

LOGURU_PATH = Path(loguru.__file__).parent


class LoguruInspectionFailed(RuntimeWarning):
"""Warning raised when magic introspection of loguru stack frames fails.

This may happen if the loguru library changes in a way that breaks the introspection.
"""


class LogfireHandler(LogfireLoggingHandler):
"""A loguru handler that sends logs to **Logfire**."""
Expand All @@ -38,51 +48,49 @@ def fill_attributes(self, record: LogRecord) -> dict[str, Any]:
while frame: # pragma: no branch
if frame.f_code is _LOG_METHOD_CODE:
frame_locals = frame.f_locals
if 'message' in frame_locals:
if 'message' in frame_locals: # pragma: no branch
attributes[ATTRIBUTES_MESSAGE_TEMPLATE_KEY] = frame_locals['message']
else: # pragma: no cover
_warn_inspection_failure()
warn_at_user_stacklevel(
'Failed to extract message template (span name) for loguru log.', LoguruInspectionFailed
)

args = frame_locals.get('args')
if isinstance(args, (tuple, list)):
if isinstance(args, (tuple, list)): # pragma: no branch
if args:
attributes[ATTRIBUTES_LOGGING_ARGS_KEY] = args
else: # pragma: no cover
_warn_inspection_failure()

if record.exc_info:
original_record = frame_locals.get('log_record')
if isinstance(original_record, dict):
message = original_record.get('message') # type: ignore
if isinstance(message, str) and record.msg.startswith(
message + '\nTraceback (most recent call last):'
):
# `record.msg` includes a traceback added by Loguru,
# replace it with the original message.
attributes[ATTRIBUTES_MESSAGE_KEY] = message
else: # pragma: no cover
_warn_inspection_failure()
else: # pragma: no cover
_warn_inspection_failure()
warn_at_user_stacklevel('Failed to extract args for loguru log.', LoguruInspectionFailed)

original_record: dict[str, Any] | None = frame_locals.get('log_record')
if (
isinstance(original_record, dict)
and isinstance(message := original_record.get('message'), str)
and message in record.msg
): # pragma: no branch
Comment on lines +66 to +70
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@alexmojaki Hi, This piece of code will drop the loguru's format, I'm wondering if this is intentional. Because the replace it with the original message only worked when the record has exc_info, but now it always does the replacement.

# example.py

import logfire
from loguru import logger

log_format = "{level: <8} | {time:YYYY-MM-DD HH:mm:ss.SSS} | {message}"

logger.remove()
logfire.configure(
    send_to_logfire='if-token-present',
    service_name='xxx',
    console=logfire.ConsoleOptions(include_timestamps=False)  # remove timestamp prefix
)
logger.add(
    logfire.loguru_handler()['sink'],
    # sink=sys.stderr,
    format=log_format,
    level="INFO",
)

logger.info('hello world')

with logfire==0.48.0, output INFO | 2024-08-13 14:15:37.811 | hello world
with logfire==0.48.1, output hello world

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes this is intentional. The integration is not designed for a loguru format. The message must be plain because it's also displayed in the UI:

Screenshot 2024-08-13 at 12 10 33

It should just be:

Screenshot 2024-08-13 at 12 11 29

How are you using logfire+loguru? Do you use the UI, or only the console? Does logfire log other non-loguru things to the console without timestamps?

The structlog integration has a console_log parameter which should probably be added to the loguru integration, so that logfire just doesn't log loguru logs to the console at all. Then timestamps don't need to be removed from other logs.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you. Currently, we use the loguru to print JSON logs to console, and then they will be collected to aws.cloudwatch, so we can do some filterings in cloudwatch, i.e., $record.extra.xxx = xxx. It's structured and easy to filter. We are still experimenting with Logfire, it's a great project, thanks. So, both systems are running in parallel, and we don't want any breaking changes on cloudwatch yet, as there is a lot of predefined filtering in it.

# example.py
import logfire
from loguru import logger

log_format = "{level: <8} | {time:YYYY-MM-DD HH:mm:ss.SSS} | {message}"

logger.remove()
logfire.configure(
    send_to_logfire='if-token-present',
    service_name='xxx',
    console=logfire.ConsoleOptions(include_timestamps=False)  # remove timestamp prefix
)
logger.add(
    logfire.loguru_handler()['sink'],
    # sink=sys.stderr,
    format=log_format,
    level="INFO",
    serialize=True,   # so it will print the logs in JSON format
)

with logfire==0.48.0, it will print the JSON logs to stderr.

{"text": "INFO     | 2024-08-14 09:25:58.212 | hello world", "record": {"elapsed": {"repr": "0:00:00.228754", "seconds": 0.228754}, "exception": null, "extra": {}, "file": {"name": "example.py", "path": "/Users/toddzhang/test/fastapi-test/tests/example.py"}, "function": "<module>", "level": {"icon": "ℹ️", "name": "INFO", "no": 20}, "line": 21, "message": "hello world", "module": "example", "name": "__main__", "process": {"id": 47410, "name": "MainProcess"}, "thread": {"id": 8462629568, "name": "MainThread"}, "time": {"repr": "2024-08-14 09:25:58.212465+08:00", "timestamp": 1723598758.212465}}}

with logfire==0.48.1, just plain text hello world

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if there's a way, we print the JSON logs to console/stderr for collection by AWS, and only display plain text on the Logfire UI?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't have permission to visit this Slack thread. But I found that I can add two sinks for loguru

  • one is sys.stderr, and we can print JSON messages to the console.
  • another is the logfire.loguru_handler()['sink'], and configure logfire with console=False

So, the log messages sent to logfire are pure text, and the messages printed to the console are in JSON format.

Thanks for your help.😊

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

See https://docs.pydantic.dev/logfire/help/ for the link to join the slack.

Are you not creating any logfire logs/spans outside of integrating with loguru? You're not using any other integrations?

# `record.msg` may include a traceback added by Loguru,
# replace it with the original message.
attributes[ATTRIBUTES_MESSAGE_KEY] = message
else: # pragma: no cover
warn_at_user_stacklevel(
'Failed to extract original message for loguru log.', LoguruInspectionFailed
)

break

frame = frame.f_back
else: # pragma: no cover
warn_at_user_stacklevel(
'Failed to find loguru log frame to extract detailed information', LoguruInspectionFailed
)

return attributes


def _warn_inspection_failure() -> None: # pragma: no cover
warnings.warn(
'Failed to extract info from loguru logger. '
'This may affect span names and/or positional arguments. '
'Please report an issue to logfire.',
RuntimeWarning,
)


try:
_LOG_METHOD_CODE = inspect.unwrap(type(logger)._log).__code__ # type: ignore
_LOG_METHOD_CODE = inspect.unwrap(type(loguru.logger)._log).__code__ # type: ignore
except Exception: # pragma: no cover
_LOG_METHOD_CODE = None # type: ignore
_warn_inspection_failure()
warn_at_user_stacklevel(
'Failed to find loguru log method code to extract detailed information', LoguruInspectionFailed
)