fix: Prefix SDK log messages

Author: marandaneto

.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/client.py

@@ -37,6 +37,7 @@
     mark_exception_as_captured,
     try_attach_code_variables_to_frames,
 )
+from posthog.logging_utils import get_posthog_logger
 from posthog.feature_flag_evaluations import (
     FeatureFlagEvaluations,
     _EvaluatedFlagRecord,
@@ -174,7 +175,7 @@ class Client(object):
         ```
     """
 
-    log = logging.getLogger("posthog")
+    log = get_posthog_logger()
 
     def __init__(
         self,

posthog/consumer.py

@@ -1,9 +1,9 @@
 from typing import Any
 import json
-import logging
 import time
 from threading import Thread
 
+from posthog.logging_utils import get_posthog_logger
 from posthog.request import (
     AI_EVENTS_ENDPOINT,
     EVENTS_ENDPOINT,
@@ -31,7 +31,7 @@
 class Consumer(Thread):
     """Consumes the messages from the client's queue."""
 
-    log = logging.getLogger("posthog")
+    log = get_posthog_logger()
 
     def __init__(
         self,

posthog/logging_utils.py

@@ -0,0 +1,32 @@
+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())
+
+
+def get_posthog_logger() -> logging.Logger:
+    configure_posthog_logging()
+    return logging.getLogger(POSTHOG_LOGGER_NAME)

posthog/request.py

@@ -1,5 +1,4 @@
 import json
-import logging
 import re
 import socket
 from dataclasses import dataclass
@@ -13,6 +12,7 @@
 from urllib3.connection import HTTPConnection
 from urllib3.util.retry import Retry
 
+from posthog.logging_utils import get_posthog_logger
 from posthog.utils import remove_trailing_slash
 from posthog.version import VERSION
 
@@ -226,7 +226,7 @@ def post(
     **kwargs,
 ) -> requests.Response:
     """Post the `kwargs` to the API"""
-    log = logging.getLogger("posthog")
+    log = get_posthog_logger()
     body = kwargs
     body["sent_at"] = datetime.now(tz=timezone.utc).isoformat()
     trimmed_host = remove_trailing_slash(normalize_host(host))
@@ -257,7 +257,7 @@ def post(
 def _process_response(
     res: requests.Response, success_message: str, *, return_json: bool = True
 ) -> Union[requests.Response, Any]:
-    log = logging.getLogger("posthog")
+    log = get_posthog_logger()
     if res.status_code == 200:
         log.debug(success_message)
         response = res.json() if return_json else res
@@ -378,7 +378,7 @@ def get(
     - not_modified=True and data=None if server returns 304
     - not_modified=False and data=response if server returns 200
     """
-    log = logging.getLogger("posthog")
+    log = get_posthog_logger()
     trimmed_host = remove_trailing_slash(normalize_host(host))
     full_url = trimmed_host + url
     headers = {"Authorization": "Bearer %s" % api_key, "User-Agent": USER_AGENT}

posthog/test/logging_helpers.py

@@ -0,0 +1,25 @@
+import io
+import logging
+from contextlib import contextmanager
+from typing import Iterator
+
+
+@contextmanager
+def capture_message_only_logs(level: int = logging.DEBUG) -> Iterator[io.StringIO]:
+    logger = logging.getLogger("posthog")
+    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 time
 import unittest
 from datetime import datetime
@@ -9,6 +10,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
@@ -80,6 +82,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)
@@ -386,7 +406,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):
@@ -396,7 +416,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(