fix: Prefix SDK log messages

.changeset/polite-wolves-warn.md

@@ -0,0 +1,5 @@
+---
+'pypi/posthog': patch
+---
+
+Prefix PostHog SDK log messages so they remain identifiable with message-only logging formatters.

posthog/_logging.py

@@ -0,0 +1,27 @@
+import logging
+
+
+_POSTHOG_LOG_PREFIX = "[PostHog]"
+_POSTHOG_LOGGER_NAME = "posthog"
+
+
+class _PostHogLogPrefixFilter(logging.Filter):
+    """Ensure PostHog SDK log messages are identifiable with message-only formatters."""
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        if getattr(record, "_posthog_log_prefix_applied", False):
+            return True
+
+        message = record.getMessage()
+        if not message.startswith(_POSTHOG_LOG_PREFIX):
+            record.msg = f"{_POSTHOG_LOG_PREFIX} {message}"
+            record.args = ()
+
+        record._posthog_log_prefix_applied = True
+        return True
+
+
+def _configure_posthog_logging() -> None:
+    logger = logging.getLogger(_POSTHOG_LOGGER_NAME)
+    if not any(isinstance(f, _PostHogLogPrefixFilter) for f in logger.filters):
+        logger.addFilter(_PostHogLogPrefixFilter())

posthog/client.py

@@ -33,6 +33,7 @@
     tag as _context_tag,
 )
 from posthog.exception_capture import ExceptionCapture
+from posthog._logging import _configure_posthog_logging
 from posthog.exception_utils import (
     DEFAULT_CODE_VARIABLES_IGNORE_PATTERNS,
     DEFAULT_CODE_VARIABLES_MASK_PATTERNS,
@@ -103,6 +104,8 @@
 from queue import Queue, Full
 
 
+_configure_posthog_logging()
+
 MAX_DICT_SIZE = 50_000
 
 

posthog/consumer.py

@@ -4,6 +4,7 @@
 import time
 from threading import Thread
 
+from posthog._logging import _configure_posthog_logging
 from posthog.request import (
     AI_EVENTS_ENDPOINT,
     EVENTS_ENDPOINT,
@@ -28,6 +29,9 @@
 BATCH_SIZE_LIMIT = 5 * 1024 * 1024
 
 
+_configure_posthog_logging()
+
+
 class Consumer(Thread):
     """Consumes the messages from the client's queue."""
 

posthog/request.py

@@ -13,6 +13,7 @@
 from urllib3.connection import HTTPConnection
 from urllib3.util.retry import Retry
 
+from posthog._logging import _configure_posthog_logging
 from posthog.utils import remove_trailing_slash
 from posthog.version import VERSION
 
@@ -196,6 +197,9 @@ def disable_connection_reuse() -> None:
 USER_AGENT = "posthog-python/" + VERSION
 
 
+_configure_posthog_logging()
+
+
 def normalize_host(host: Optional[str]) -> str:
     """Normalize a configured host, defaulting blank values to DEFAULT_HOST."""
     normalized_host = (host or "").strip()

posthog/test/logging_helpers.py

@@ -0,0 +1,27 @@
+import io
+import logging
+from contextlib import contextmanager
+from typing import Iterator
+
+from posthog._logging import _POSTHOG_LOGGER_NAME
+
+
+@contextmanager
+def capture_message_only_logs(level: int = logging.DEBUG) -> Iterator[io.StringIO]:
+    logger = logging.getLogger(_POSTHOG_LOGGER_NAME)
+    stream = io.StringIO()
+    handler = logging.StreamHandler(stream)
+    handler.setFormatter(logging.Formatter("%(message)s"))
+
+    previous_level = logger.level
+    previous_propagate = logger.propagate
+    logger.addHandler(handler)
+    logger.setLevel(level)
+    logger.propagate = False
+    try:
+        yield stream
+    finally:
+        logger.removeHandler(handler)
+        handler.close()
+        logger.setLevel(previous_level)
+        logger.propagate = previous_propagate

posthog/test/test_client.py

@@ -1,3 +1,4 @@
+import logging
 import asyncio
 import time
 import unittest
@@ -10,6 +11,7 @@
 from posthog.client import Client
 from posthog.contexts import get_context_session_id, new_context, set_context_session
 from posthog.request import APIError, GetResponse
+from posthog.test.logging_helpers import capture_message_only_logs
 from posthog.test.test_utils import FAKE_TEST_API_KEY
 from posthog.types import FeatureFlag, LegacyFlagMetadata
 from posthog.version import VERSION
@@ -81,6 +83,24 @@ def test_client_with_empty_api_key_is_noop(self):
 
         self.assertIsNone(client.capture("event", distinct_id="distinct_id"))
 
+    def test_message_only_info_logs_include_posthog_prefix(self):
+        self.client.flag_cache = mock.Mock()
+        self.client.flag_cache.get_stale_cached_flag.return_value = mock.Mock()
+
+        with capture_message_only_logs(level=logging.INFO) as logs:
+            self.client._get_stale_flag_fallback("distinct_id", "flag-key")
+
+        self.assertEqual(
+            logs.getvalue().strip(),
+            "[PostHog] [FEATURE FLAGS] Using stale cached value for flag flag-key",
+        )
+
+    def test_message_only_logs_do_not_duplicate_existing_posthog_prefix(self):
+        with capture_message_only_logs(level=logging.ERROR) as logs:
+            self.client.log.error("[PostHog] already prefixed")
+
+        self.assertEqual(logs.getvalue().strip(), "[PostHog] already prefixed")
+
     @mock.patch("posthog.client.get")
     def test_disabled_client_does_not_load_feature_flags(self, patch_get):
         client = Client("", personal_api_key="test", send=False)
@@ -454,7 +474,7 @@ def test_basic_capture_exception_with_no_exception_happening(self):
                 self.assertFalse(patch_capture.called)
                 self.assertEqual(
                     logs.output[0],
-                    "WARNING:posthog:No exception information available",
+                    "WARNING:posthog:[PostHog] No exception information available",
                 )
 
     def test_capture_exception_logs_when_enabled(self):
@@ -464,7 +484,7 @@ def test_capture_exception_logs_when_enabled(self):
                 Exception("test exception"), distinct_id="distinct_id"
             )
             self.assertEqual(
-                logs.output[0], "ERROR:posthog:test exception\nNoneType: None"
+                logs.output[0], "ERROR:posthog:[PostHog] test exception\nNoneType: None"
             )
 
     @mock.patch("posthog.client.flags")

posthog/test/test_consumer.py

@@ -13,6 +13,7 @@
 
 from posthog.consumer import MAX_MSG_SIZE, Consumer
 from posthog.request import APIError
+from posthog.test.logging_helpers import capture_message_only_logs
 from posthog.test.test_utils import TEST_API_KEY
 
 
@@ -54,6 +55,18 @@ def test_upload(self) -> None:
         success = consumer.upload()
         self.assertTrue(success)
 
+    def test_message_only_error_logs_include_posthog_prefix(self) -> None:
+        q = Queue()
+        consumer = Consumer(q, TEST_API_KEY)
+        q.put(_track_event())
+
+        with mock.patch.object(consumer, "request", side_effect=Exception("boom")):
+            with capture_message_only_logs() as logs:
+                success = consumer.upload()
+
+        self.assertFalse(success)
+        self.assertEqual(logs.getvalue().strip(), "[PostHog] error uploading: boom")
+
     def test_flush_interval(self) -> None:
         # Put _n_ items in the queue, pausing a little bit more than
         # _flush_interval_ after each one.

posthog/test/test_exception_capture.py

@@ -149,7 +149,7 @@ def test_excepthook(tmpdir):
 
     assert b"ZeroDivisionError" in output
     assert b"LOL" in output
-    assert b"DEBUG:posthog:data uploaded successfully" in output
+    assert b"DEBUG:posthog:[PostHog] data uploaded successfully" in output
     assert (
         b'"$exception_list": [{"mechanism": {"type": "generic", "handled": true}, "module": null, "type": "ZeroDivisionError", "value": "division by zero", "stacktrace": {"frames": [{"platform": "python", "filename": "app.py", "abs_path"'
         in output

posthog/test/test_request.py

@@ -7,6 +7,7 @@
 import requests
 
 import posthog.request as request_module
+from posthog.test.logging_helpers import capture_message_only_logs
 from posthog.request import (
     APIError,
     DatetimeSerializer,
@@ -84,6 +85,28 @@ def test_post_sends_snake_case_sent_at(key, expected_present):
     assert (key in data) is expected_present
 
 
+def test_message_only_debug_logs_include_posthog_prefix():
+    mock_response = requests.Response()
+    mock_response.status_code = 200
+    mock_session = mock.MagicMock()
+    mock_session.post.return_value = mock_response
+
+    with capture_message_only_logs() as logs:
+        request_module.post(
+            TEST_API_KEY,
+            host="https://test.posthog.com",
+            path="/batch/",
+            session=mock_session,
+            batch=[],
+        )
+
+    assert logs.getvalue().splitlines() == [
+        mock.ANY,
+        "[PostHog] data uploaded successfully",
+    ]
+    assert logs.getvalue().splitlines()[0].startswith("[PostHog] making request: ")
+
+
 class TestRequests(unittest.TestCase):
     def test_valid_request(self):
         res = batch_post(