From 939ff78a36a1bcc685dd4e8273cc53feb6421c9e Mon Sep 17 00:00:00 2001 From: Quinn Milionis Date: Sun, 14 Dec 2025 22:17:41 -0800 Subject: [PATCH 1/2] remove calls to shutdown in close method add try/finally catch to emit method --- scout_apm_logging/handler.py | 89 +++++++++++++++++++----------------- 1 file changed, 48 insertions(+), 41 deletions(-) diff --git a/scout_apm_logging/handler.py b/scout_apm_logging/handler.py index 220de09..b8c78b5 100644 --- a/scout_apm_logging/handler.py +++ b/scout_apm_logging/handler.py @@ -1,13 +1,15 @@ import logging import os import threading + from opentelemetry import _logs from opentelemetry.exporter.otlp.proto.grpc._log_exporter import OTLPLogExporter from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler from opentelemetry.sdk._logs.export import BatchLogRecordProcessor from opentelemetry.sdk.resources import Resource -from scout_apm.core.tracked_request import TrackedRequest from scout_apm.core import scout_config +from scout_apm.core.tracked_request import TrackedRequest + from scout_apm_logging.utils.operation_utils import get_operation_detail @@ -20,8 +22,6 @@ def __init__(self, service_name): self.logger_provider = None self.service_name = service_name self._handling_log = threading.local() - self._initialized = False - self._initializing = False def _initialize(self): with self._initialization_lock: @@ -67,46 +67,53 @@ def emit(self, record): if getattr(self._handling_log, "value", False): # We're already handling a log message, don't get the TrackedRequest return ScoutOtelHandler.otel_handler.emit(record) - - self._handling_log.value = True - scout_request = TrackedRequest.instance() - - if scout_request: - operation_detail = get_operation_detail(scout_request) - if operation_detail: - setattr( - record, - operation_detail.entrypoint_attribute, - operation_detail.name, - ) - - # Add Scout-specific attributes to the log record - record.scout_transaction_id = scout_request.request_id - record.scout_start_time = scout_request.start_time.isoformat() - # Add duration if the request is completed - if scout_request.end_time: - record.scout_end_time = scout_request.end_time.isoformat() - record.scout_duration = ( - scout_request.end_time - scout_request.start_time - ).total_seconds() - - setattr(record, "service.name", self.service_name) - - # Add tags - for key, value in scout_request.tags.items(): - setattr(record, f"scout_tag_{key}", value) - - # Add the current span's operation if available - current_span = scout_request.current_span() - if current_span: - record.scout_current_operation = current_span.operation - - ScoutOtelHandler.otel_handler.emit(record) - self._handling_log.value = False + try: + self._handling_log.value = True + scout_request = TrackedRequest.instance() + + if scout_request: + operation_detail = get_operation_detail(scout_request) + if operation_detail: + setattr( + record, + operation_detail.entrypoint_attribute, + operation_detail.name, + ) + + # Add Scout-specific attributes to the log record + record.scout_transaction_id = scout_request.request_id + record.scout_start_time = scout_request.start_time.isoformat() + # Add duration if the request is completed + if scout_request.end_time: + record.scout_end_time = scout_request.end_time.isoformat() + record.scout_duration = ( + scout_request.end_time - scout_request.start_time + ).total_seconds() + + setattr(record, "service.name", self.service_name) + + # Add tags + for key, value in scout_request.tags.items(): + setattr(record, f"scout_tag_{key}", value) + + # Add the current span's operation if available + current_span = scout_request.current_span() + if current_span: + record.scout_current_operation = current_span.operation + + ScoutOtelHandler.otel_handler.emit(record) + finally: + self._handling_log.value = False def close(self): - if self.logger_provider: - self.logger_provider.shutdown() + """ + We intentionally don't shutdown the LoggerProvider here because: + 1. We use a singleton pattern - the LoggerProvider is shared between instances. + 2. Django calls close() during configuration, not just on shutdown. + + The LoggerProvider manages its own lifecycle and will call shutdown() when the + application exits. + """ super().close() # These getters will be replaced by a config module to read these values From b52e23a6001e1d2c804c97d45a35502307eecaf6 Mon Sep 17 00:00:00 2001 From: Quinn Milionis Date: Mon, 15 Dec 2025 09:48:19 -0800 Subject: [PATCH 2/2] replace close test with test emit reset handling log --- tests/unit/test_handler.py | 50 ++++++++++++++++++++++++++------------ 1 file changed, 35 insertions(+), 15 deletions(-) diff --git a/tests/unit/test_handler.py b/tests/unit/test_handler.py index fc986b3..5f49dcc 100644 --- a/tests/unit/test_handler.py +++ b/tests/unit/test_handler.py @@ -1,24 +1,25 @@ -import pytest -import logging import io -from unittest.mock import patch, MagicMock -from scout_apm_logging.handler import ScoutOtelHandler +import logging +from unittest.mock import MagicMock, patch + +import pytest from scout_apm.core.tracked_request import Span +from scout_apm_logging.handler import ScoutOtelHandler + @pytest.fixture def otel_scout_handler(): # Reset class initialization state ScoutOtelHandler.otel_handler = None - with patch("scout_apm_logging.handler.scout_config") as mock_scout_config, patch( - "scout_apm_logging.handler.OTLPLogExporter" - ), patch("scout_apm_logging.handler.LoggerProvider"), patch( - "scout_apm_logging.handler.BatchLogRecordProcessor" - ), patch( - "scout_apm_logging.handler.Resource" + with ( + patch("scout_apm_logging.handler.scout_config") as mock_scout_config, + patch("scout_apm_logging.handler.OTLPLogExporter"), + patch("scout_apm_logging.handler.LoggerProvider"), + patch("scout_apm_logging.handler.BatchLogRecordProcessor"), + patch("scout_apm_logging.handler.Resource"), ): - mock_scout_config.value.return_value = "test-ingest-key" handler = ScoutOtelHandler(service_name="test-service") # Force initialization @@ -141,10 +142,29 @@ def test_emit_already_handling_log(otel_scout_handler): otel_scout_handler._handling_log.value = False -def test_close(otel_scout_handler): - with patch.object(otel_scout_handler.logger_provider, "shutdown") as mock_shutdown: - otel_scout_handler.close() - mock_shutdown.assert_called_once() +@patch("scout_apm_logging.handler.TrackedRequest") +def test_emit_resets_handling_log_on_exception( + mock_tracked_request, otel_scout_handler +): + """Verify _handling_log.value is reset even when an exception occurs during emit.""" + mock_tracked_request.instance.side_effect = RuntimeError("Test exception") + + with patch.object(ScoutOtelHandler, "otel_handler"): + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="Test message", + args=(), + exc_info=None, + ) + + with pytest.raises(RuntimeError, match="Test exception"): + otel_scout_handler.emit(record) + + # The key assertion: _handling_log should be reset to False + assert otel_scout_handler._handling_log.value is False @patch("scout_apm_logging.handler.scout_config")