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.

Sign up for GitHub

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

Jump to bottom

Fix recursive logging from OTEL's BatchSpanProcessor #306

Merged
merged 5 commits into from
Jul 8, 2024
Merged

Fix recursive logging from OTEL's BatchSpanProcessor #306

merged 5 commits into from
Jul 8, 2024

Conversation

alexmojaki
Copy link
Contributor

Fixes a problem reported in https://pydanticlogfire.slack.com/archives/C06EDRBSAH3/p1720181277066769

Script to reproduce a similar problem before this PR:

import atexit
import logging
from logging import basicConfig

import logfire

atexit.register(lambda *_: logging.error('!!!!'))

logfire.configure(console=False)

basicConfig(handlers=[logfire.LogfireLoggingHandler()])

for _ in range(10000):
    logfire.info('hi')

The logging in a loop fills up the queue which leads to this hellish traceback being logged:

Internal error in Logfire
Traceback (most recent call last):
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 236, in handle_internal_errors
    yield
  File "/Users/alex/work/logfire/logfire/_internal/main.py", line 654, in log
    span = tracer.start_span(
           ^^^^^^^^^^^^^^^^^^
  File "/Users/alex/work/logfire/logfire/_internal/tracer.py", line 188, in start_span
    span = self.tracer.start_span(
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/__init__.py", line 1165, in start_span
    span.start(start_time=start_time, parent_context=context)
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/__init__.py", line 922, in start
    self._span_processor.on_start(self, parent_context=parent_context)
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/__init__.py", line 164, in on_start
    sp.on_start(span, parent_context=parent_context)
  File "/Users/alex/work/logfire/logfire/_internal/exporters/processor_wrapper.py", line 41, in on_start
    if is_instrumentation_suppressed():
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 212, in is_instrumentation_suppressed
    return any(context.get_value(key) for key in SUPPRESS_INSTRUMENTATION_CONTEXT_KEYS)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 212, in <genexpr>
    return any(context.get_value(key) for key in SUPPRESS_INSTRUMENTATION_CONTEXT_KEYS)
               ^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/context/__init__.py", line 96, in get_value
    return context.get(key) if context is not None else get_current().get(key)
                                                        ^^^^^^^^^^^^^
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/context/__init__.py", line 130, in get_current
    return _RUNTIME_CONTEXT.get_current()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
RecursionError: maximum recursion depth exceeded

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 236, in handle_internal_errors
    yield
  File "/Users/alex/work/logfire/logfire/_internal/main.py", line 670, in log
    span.end(start_time)
  File "/Users/alex/work/logfire/logfire/_internal/tracer.py", line 103, in end
    self.span.end(end_time or self.ns_timestamp_generator())
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/__init__.py", line 934, in end
    self._span_processor.on_end(self._readable_span())
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/__init__.py", line 168, in on_end
    sp.on_end(span)
  File "/Users/alex/work/logfire/logfire/_internal/exporters/processor_wrapper.py", line 55, in on_end
    super().on_end(span)
  File "/Users/alex/work/logfire/logfire/_internal/exporters/wrapper.py", line 60, in on_end
    self.processor.on_end(span)
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/export/__init__.py", line 228, in on_end
    logger.warning("Queue is full, likely spans will be dropped.")
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1551, in warning
    self._log(WARNING, msg, args, **kwargs)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1684, in _log
    self.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1028, in handle
    self.emit(record)
  File "/Users/alex/work/logfire/logfire/integrations/logging.py", line 70, in emit
    logfire.log(
  File "/Users/alex/work/logfire/logfire/_internal/main.py", line 591, in log
    with handle_internal_errors():
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 238, in handle_internal_errors
    log_internal_error()
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 230, in log_internal_error
    logger.exception('Internal error in Logfire')
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1574, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1568, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1682, in _log
    record = self.makeRecord(self.name, level, fn, lno, msg, args,
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1651, in makeRecord
    rv = _logRecordFactory(name, level, fn, lno, msg, args, exc_info, func,
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 332, in __init__
    self.filename = os.path.basename(pathname)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "<frozen posixpath>", line 172, in basename
RecursionError: maximum recursion depth exceeded

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 236, in handle_internal_errors
    yield
  File "/Users/alex/work/logfire/logfire/_internal/main.py", line 670, in log
    span.end(start_time)
  File "/Users/alex/work/logfire/logfire/_internal/tracer.py", line 103, in end
    self.span.end(end_time or self.ns_timestamp_generator())
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/__init__.py", line 934, in end
    self._span_processor.on_end(self._readable_span())
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/__init__.py", line 168, in on_end
    sp.on_end(span)
  File "/Users/alex/work/logfire/logfire/_internal/exporters/processor_wrapper.py", line 55, in on_end
    super().on_end(span)
  File "/Users/alex/work/logfire/logfire/_internal/exporters/wrapper.py", line 60, in on_end
    self.processor.on_end(span)
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/export/__init__.py", line 228, in on_end
    logger.warning("Queue is full, likely spans will be dropped.")
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1551, in warning
    self._log(WARNING, msg, args, **kwargs)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1684, in _log
    self.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1028, in handle
    self.emit(record)
  File "/Users/alex/work/logfire/logfire/integrations/logging.py", line 70, in emit
    logfire.log(
  File "/Users/alex/work/logfire/logfire/_internal/main.py", line 591, in log
    with handle_internal_errors():
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 238, in handle_internal_errors
    log_internal_error()
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 230, in log_internal_error
    logger.exception('Internal error in Logfire')
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1574, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1568, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1684, in _log
    self.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1028, in handle
    self.emit(record)
  File "/Users/alex/work/logfire/logfire/integrations/logging.py", line 65, in emit
    self.fallback.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1028, in handle
    self.emit(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1160, in emit
    msg = self.format(record)
          ^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 999, in format
    return fmt.format(record)
           ^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 711, in format
    record.exc_text = self.formatException(record.exc_info)
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 661, in formatException
    traceback.print_exception(ei[0], ei[1], tb, None, sio)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/traceback.py", line 124, in print_exception
    te = TracebackException(type(value), value, tb, limit=limit, compact=True)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/traceback.py", line 733, in __init__
    self.stack = StackSummary._extract_from_extended_frame_gen(
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/traceback.py", line 438, in _extract_from_extended_frame_gen
    f.line
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/traceback.py", line 323, in line
    self._line = linecache.getline(self.filename, self.lineno)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/linecache.py", line 30, in getline
    lines = getlines(filename, module_globals)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/linecache.py", line 46, in getlines
    return updatecache(filename, module_globals)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/linecache.py", line 136, in updatecache
    with tokenize.open(fullname) as fp:
         ^^^^^^^^^^^^^^^^^^^^^^^
RecursionError: maximum recursion depth exceeded

and the attempt to log something when shutting down logs:

Internal error in Logfire
Traceback (most recent call last):
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 236, in handle_internal_errors
    yield
  File "/Users/alex/work/logfire/logfire/_internal/main.py", line 670, in log
    span.end(start_time)
  File "/Users/alex/work/logfire/logfire/_internal/tracer.py", line 103, in end
    self.span.end(end_time or self.ns_timestamp_generator())
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/__init__.py", line 934, in end
    self._span_processor.on_end(self._readable_span())
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/__init__.py", line 168, in on_end
    sp.on_end(span)
  File "/Users/alex/work/logfire/logfire/_internal/exporters/processor_wrapper.py", line 55, in on_end
    super().on_end(span)
  File "/Users/alex/work/logfire/logfire/_internal/exporters/wrapper.py", line 60, in on_end
    self.processor.on_end(span)
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/export/__init__.py", line 219, in on_end
    logger.warning("Already shutdown, dropping span.")
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1551, in warning
    self._log(WARNING, msg, args, **kwargs)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1684, in _log
    self.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1028, in handle
    self.emit(record)
  File "/Users/alex/work/logfire/logfire/integrations/logging.py", line 64, in emit
    if is_instrumentation_suppressed():
       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 212, in is_instrumentation_suppressed
    return any(context.get_value(key) for key in SUPPRESS_INSTRUMENTATION_CONTEXT_KEYS)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 212, in <genexpr>
    return any(context.get_value(key) for key in SUPPRESS_INSTRUMENTATION_CONTEXT_KEYS)
               ^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/context/__init__.py", line 96, in get_value
    return context.get(key) if context is not None else get_current().get(key)
                                                        ^^^^^^^^^^^^^
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/context/__init__.py", line 130, in get_current
    return _RUNTIME_CONTEXT.get_current()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
RecursionError: maximum recursion depth exceeded

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 236, in handle_internal_errors
    yield
  File "/Users/alex/work/logfire/logfire/_internal/main.py", line 670, in log
    span.end(start_time)
  File "/Users/alex/work/logfire/logfire/_internal/tracer.py", line 103, in end
    self.span.end(end_time or self.ns_timestamp_generator())
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/__init__.py", line 934, in end
    self._span_processor.on_end(self._readable_span())
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/__init__.py", line 168, in on_end
    sp.on_end(span)
  File "/Users/alex/work/logfire/logfire/_internal/exporters/processor_wrapper.py", line 55, in on_end
    super().on_end(span)
  File "/Users/alex/work/logfire/logfire/_internal/exporters/wrapper.py", line 60, in on_end
    self.processor.on_end(span)
  File "/Users/alex/work/logfire/.venv/lib/python3.12/site-packages/opentelemetry/sdk/trace/export/__init__.py", line 219, in on_end
    logger.warning("Already shutdown, dropping span.")
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1551, in warning
    self._log(WARNING, msg, args, **kwargs)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1684, in _log
    self.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1028, in handle
    self.emit(record)
  File "/Users/alex/work/logfire/logfire/integrations/logging.py", line 70, in emit
    logfire.log(
  File "/Users/alex/work/logfire/logfire/_internal/main.py", line 591, in log
    with handle_internal_errors():
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/contextlib.py", line 158, in __exit__
    self.gen.throw(value)
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 238, in handle_internal_errors
    log_internal_error()
  File "/Users/alex/work/logfire/logfire/_internal/utils.py", line 230, in log_internal_error
    logger.exception('Internal error in Logfire')
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1574, in exception
    self.error(msg, *args, exc_info=exc_info, **kwargs)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1568, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1684, in _log
    self.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1700, in handle
    self.callHandlers(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1762, in callHandlers
    hdlr.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1028, in handle
    self.emit(record)
  File "/Users/alex/work/logfire/logfire/integrations/logging.py", line 65, in emit
    self.fallback.handle(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1028, in handle
    self.emit(record)
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 1160, in emit
    msg = self.format(record)
          ^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 999, in format
    return fmt.format(record)
           ^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 706, in format
    s = self.formatMessage(record)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 675, in formatMessage
    return self._style.format(record)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/Users/alex/.rye/py/[email protected]/lib/python3.12/logging/__init__.py", line 464, in format
    return self._format(record)
           ^^^^^^^^^^^^^^^^^^^^
RecursionError: maximum recursion depth exceeded

Both of these are fixed here with one with logfire.suppress_instrumentation(): in MainSpanProcessorWrapper.on_end. Similar lines are added elsewhere for extra caution.

Also refactored some tests similar to the one I added.

@codecov Codecov
Copy link

codecov bot commented Jul 5, 2024 •
edited
Loading

Codecov Report

All modified and coverable lines are covered by tests ✅

📢 Thoughts on this report? Let us know!

@cloudflare-pages Cloudflare Pages
Copy link

cloudflare-pages bot commented Jul 5, 2024 •
edited
Loading

Deploying logfire-docs with  Cloudflare Pages  Cloudflare Pages

Latest commit: a79b953
Status: ✅  Deploy successful!
Preview URL: https://dbbc73b2.logfire-docs.pages.dev
Branch Preview URL: https://alex-bsp-logs.logfire-docs.pages.dev

View logs

@alexmojaki alexmojaki requested a review from Kludex July 5, 2024 21:50
@alexmojaki alexmojaki merged commit 5d6ef9a into main Jul 8, 2024
12 checks passed
@alexmojaki alexmojaki deleted the alex/bsp-logs branch July 8, 2024 11:06
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@adriangb adriangb adriangb approved these changes

@Kludex Kludex Awaiting requested review from Kludex

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

None yet
2 participants
@alexmojaki @adriangb