Django configuration compatibility (#24)

* use lazy initialization with a class lock

* add urls and scout support as authors

* mock test-ingest-key in fixture

* set handling log after check
fix existing tests

* add test of new initialize logic

* make otel_handler a class variable

Author: quinnmil

pyproject.toml

@@ -1,10 +1,16 @@
 [tool.poetry]
 name = "scout-apm-logging"
-version = "1.0.0"
+version = "1.0.1"
 description = "Scout APM Python Logging Agent"
-authors = ["Quinn Milionis <[email protected]>"]
+authors = ["Scout <[email protected]>"]
+maintainers = ["Quinn Milionis <[email protected]>"]
 readme = "README.md"
 
+[tool.poetry.urls]
+homepage = "https://scoutapm.com"
+repository = "https://github.com/scoutapp/scout_apm_python_logging"
+documentation = "https://scoutapm.com/docs/features/log-management"
+
 [tool.poetry.dependencies]
 python = "^3.9"
 opentelemetry-api = "^1.26.0"

scout_apm_logging/handler.py

@@ -12,16 +12,28 @@
 
 
 class ScoutOtelHandler(logging.Handler):
+    _initialization_lock = threading.Lock()
+    otel_handler = None
+
     def __init__(self, service_name):
         super().__init__()
         self.logger_provider = None
-        self.service_name = self._get_service_name(service_name)
-        self.ingest_key = self._get_ingest_key()
-        self.endpoint = self._get_endpoint()
-        self.setup_logging()
+        self.service_name = service_name
         self._handling_log = threading.local()
+        self._initialized = False
+        self._initializing = False
+
+    def _initialize(self):
+        with self._initialization_lock:
+            if ScoutOtelHandler.otel_handler:
+                return
 
-    def setup_logging(self):
+            self.service_name = self._get_service_name(self.service_name)
+            self.ingest_key = self._get_ingest_key()
+            self.endpoint = self._get_endpoint()
+            self.setup_otel_handler()
+
+    def setup_otel_handler(self):
         self.logger_provider = LoggerProvider(
             resource=Resource.create(
                 {
@@ -40,56 +52,57 @@ def setup_logging(self):
             BatchLogRecordProcessor(otlp_exporter)
         )
 
-        self.otel_handler = LoggingHandler(
+        ScoutOtelHandler.otel_handler = LoggingHandler(
             level=logging.NOTSET, logger_provider=self.logger_provider
         )
 
     def emit(self, record):
+        if not ScoutOtelHandler.otel_handler:
+            try:
+                self._initialize()
+            except Exception as e:
+                print(f"Failed to initialize ScoutOtelHandler: {e}")
+                return
+
         if getattr(self._handling_log, "value", False):
-            # We're already handling a log message, don't try to get the TrackedRequest
-            return self.otel_handler.emit(record)
-
-        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_request_id = scout_request.request_id
-                record.scout_start_time = scout_request.start_time.isoformat()
-                if scout_request.end_time:
-                    record.scout_end_time = scout_request.end_time.isoformat()
-
-                # Add duration if the request is completed
-                if scout_request.end_time:
-                    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
-
-            self.otel_handler.emit(record)
-        except Exception as e:
-            print(f"Error in ScoutOtelHandler.emit: {e}")
-        finally:
-            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_request_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
 
     def close(self):
         if self.logger_provider:

tests/unit/test_handler.py

@@ -8,13 +8,22 @@
 
 @pytest.fixture
 def otel_scout_handler():
-    with patch("scout_apm_logging.handler.OTLPLogExporter"), patch(
-        "scout_apm_logging.handler.LoggerProvider"
-    ), patch("scout_apm_logging.handler.BatchLogRecordProcessor"), patch(
+    # 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"
     ):
+
+        mock_scout_config.value.return_value = "test-ingest-key"
         handler = ScoutOtelHandler(service_name="test-service")
-        yield handler
+        # Force initialization
+        handler._initialize()
+        return handler
 
 
 def test_init(otel_scout_handler):
@@ -37,7 +46,7 @@ def test_emit_with_scout_request(mock_tracked_request, otel_scout_handler):
     ]
     mock_tracked_request.instance.return_value = mock_request
 
-    with patch.object(otel_scout_handler, "otel_handler") as mock_otel_handler:
+    with patch.object(ScoutOtelHandler, "otel_handler") as mock_otel_handler:
         record = logging.LogRecord(
             name="test",
             level=logging.INFO,
@@ -72,7 +81,7 @@ def test_emit_when_scout_request_contains_operation(
     mock_request.operation = MagicMock().return_value = "Controller/foobar"
     mock_tracked_request.instance.return_value = mock_request
 
-    with patch.object(otel_scout_handler, "otel_handler") as mock_otel_handler:
+    with patch.object(ScoutOtelHandler, "otel_handler") as mock_otel_handler:
         record = logging.LogRecord(
             name="test",
             level=logging.INFO,
@@ -84,18 +93,18 @@ def test_emit_when_scout_request_contains_operation(
         )
         otel_scout_handler.emit(record)
 
-        mock_otel_handler.emit.assert_called_once()
-        assert record.scout_request_id == "test-id"
-        assert record.scout_start_time == "2024-03-06T12:00:00"
-        assert record.scout_end_time == "2024-03-06T12:00:01"
-        assert record.scout_tag_key == "value"
-        assert record.controller_entrypoint == "foobar"
+    mock_otel_handler.emit.assert_called_once()
+    assert record.scout_request_id == "test-id"
+    assert record.scout_start_time == "2024-03-06T12:00:00"
+    assert record.scout_end_time == "2024-03-06T12:00:01"
+    assert record.scout_tag_key == "value"
+    assert record.controller_entrypoint == "foobar"
 
 
 @patch("scout_apm_logging.handler.TrackedRequest")
 def test_emit_without_scout_request(mock_tracked_request, otel_scout_handler):
     mock_tracked_request.instance.return_value = None
-    with patch.object(otel_scout_handler, "otel_handler") as mock_otel_handler:
+    with patch.object(ScoutOtelHandler, "otel_handler") as mock_otel_handler:
         record = logging.LogRecord(
             name="test",
             level=logging.INFO,
@@ -112,7 +121,7 @@ def test_emit_without_scout_request(mock_tracked_request, otel_scout_handler):
 
 
 def test_emit_already_handling_log(otel_scout_handler):
-    with patch.object(otel_scout_handler, "otel_handler") as mock_otel_handler:
+    with patch.object(ScoutOtelHandler, "otel_handler") as mock_otel_handler:
         # Simulate that we're already handling a log message
         otel_scout_handler._handling_log.value = True
 
@@ -132,35 +141,6 @@ def test_emit_already_handling_log(otel_scout_handler):
     otel_scout_handler._handling_log.value = False
 
 
-def test_emit_exception_handling(otel_scout_handler):
-    with patch(
-        "scout_apm_logging.handler.TrackedRequest"
-    ) as mock_tracked_request, patch(
-        "sys.stdout", new_callable=io.StringIO
-    ) as mock_stdout:
-
-        mock_tracked_request.instance.side_effect = Exception("Test exception")
-
-        record = logging.LogRecord(
-            name="test",
-            level=logging.INFO,
-            pathname="",
-            lineno=0,
-            msg="Test message",
-            args=(),
-            exc_info=None,
-        )
-
-        otel_scout_handler.emit(record)
-
-        # Check that the exception was caught and the error message was printed
-        assert (
-            "Error in ScoutOtelHandler.emit: Test exception" in mock_stdout.getvalue()
-        )
-
-    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()
@@ -195,3 +175,41 @@ def test_get_ingest_key_not_set(mock_scout_config, otel_scout_handler):
     mock_scout_config.value.return_value = None
     with pytest.raises(ValueError, match="SCOUT_LOGS_INGEST_KEY is not set"):
         otel_scout_handler._get_ingest_key()
+
+
+def test_initialize_only_once(otel_scout_handler):
+    # First initialization happens in fixture
+    initial_service_name = otel_scout_handler.service_name
+
+    # Try to initialize again
+    otel_scout_handler._initialize()
+
+    # Service name should not change since second initialization should return early
+    assert otel_scout_handler.service_name == initial_service_name
+
+
+def test_emit_handles_initialization_failure():
+    with patch("scout_apm_logging.handler.scout_config") as mock_scout_config:
+        mock_scout_config.value.return_value = (
+            None  # This will cause _get_ingest_key to fail
+        )
+        ScoutOtelHandler.otel_handler = None
+
+        handler = ScoutOtelHandler(service_name="test-service")
+
+        with patch("sys.stdout", new_callable=io.StringIO) as mock_stdout:
+            record = logging.LogRecord(
+                name="test",
+                level=logging.INFO,
+                pathname="",
+                lineno=0,
+                msg="Test message",
+                args=(),
+                exc_info=None,
+            )
+            handler.emit(record)
+
+            assert (
+                "Failed to initialize ScoutOtelHandler: "
+                "SCOUT_LOGS_INGEST_KEY is not set" in mock_stdout.getvalue()
+            )