diff --git a/.sampo/changesets/capture-hook-log-and-connection-retries.md b/.sampo/changesets/capture-hook-log-and-connection-retries.md new file mode 100644 index 000000000..e5c224754 --- /dev/null +++ b/.sampo/changesets/capture-hook-log-and-connection-retries.md @@ -0,0 +1,9 @@ +--- +pypi/posthog: patch +--- + +Capture makes one connection try per attempt, so every physical request carries its own attempt number and request timestamp. 7.x also retried a failed connection up to twice inside each attempt, reusing the request timestamp, which shifted the events' stored time by the time spent connecting. + +When `before_send` raises, the error line names the event and the exception type, not the exception message. The traceback is logged at debug level. + +Events without `NaN` or `Infinity` are encoded once, without first copying them to replace non-finite numbers. Events that contain them still send those values as `null`. diff --git a/docs/migration-7.x-to-8.0.md b/docs/migration-7.x-to-8.0.md index a0f3314e7..3af270449 100644 --- a/docs/migration-7.x-to-8.0.md +++ b/docs/migration-7.x-to-8.0.md @@ -41,6 +41,14 @@ You need to change code if your app does any of these: If you send events to a self-hosted PostHog, check that it serves both endpoints before you upgrade. An endpoint that is not served drops every event sent to it. +If you send events through your own reverse proxy, update it before you upgrade: + +- Forward `/i/v1/analytics/events` and `/i/v1/ai/events` to PostHog. +- Pass `Authorization` (the project token, sent as `Bearer `), every `PostHog-*` header, `Content-Type`, `Content-Encoding` and `User-Agent` through unchanged. PostHog answers `401` without `Authorization` and `400` without the others, and the batch fails. +- Accept request bodies up to 20 MB. AI requests are often larger than 1 MB, the default limit in nginx and ingress-nginx. A `413` from the proxy fails the batch. + +PostHog's managed reverse proxy already does this. See the [proxy guides](https://posthog.com/docs/advanced/proxy). + The SDK follows a `307` or `308` redirect only to the origin of `host` (same scheme, host and port), at most 5 times. Any other redirect fails the batch and reaches `on_error`. In 7.x the sync client followed redirects to any origin. @@ -103,8 +111,9 @@ When the whole request is over the billing limit, capture returns a `402` with n - In `sync_mode`, a failed `capture()` calls `on_error` and returns `None`. With `debug=True` it calls `on_error` and then re-raises the error. - If a capture inside `on_error` fails, the SDK logs the failure and does not call `on_error` again. - The SDK retries `408`, `500`, `502`, `503` and `504` responses and network errors. Other error statuses fail the batch at once, including `429` and the other 5xx codes. 7.x also retried `429` and every 5xx. Capture itself does not return `429`; a proxy in front of it can. +- Each attempt makes one connection try. 7.x also retried a failed connection up to twice inside each attempt, so a capture request could block for up to three times the `timeout` per attempt. - Retries start at 100 ms and double each attempt, up to 30 seconds. Each wait varies randomly by up to 25%, so many clients do not retry at the same moment. A `Retry-After` header sets a minimum wait, up to 30 seconds. The `Consumer` default is 3 retries, down from 10. -- The SDK's own log lines no longer contain event content: the debug line for a queued event names the event and the lane, and the invalid timestamp warning no longer includes the value. An exception your `before_send` hook raises is still logged with its message. To inspect events, use `before_send`. +- The SDK's own log lines no longer contain event content: the debug line for a queued event names the event and the lane, and the invalid timestamp warning no longer includes the value. When your `before_send` hook raises, the error line names the event and the exception type, not the exception message, which can hold the data the hook was removing. The traceback is logged at debug level. To inspect events, use `before_send`. - A personal API key (`phx_...`) passed as the project API key disables the client and logs one error, as an empty key does. Capture rejects personal API keys, and the SDK no longer sends one with every request. ## Invalid events @@ -181,6 +190,7 @@ Capture v1 sends processing options in an `options` object, next to `properties` | --- | --- | | `$cookieless_mode` | `cookieless_mode` | | `$ignore_sent_at` | `disable_skew_correction` | + | `$product_tour_id` | `product_tour_id` | | `$process_person_profile` | `process_person_profile` | - An option set at any layer wins over its legacy property set at any layer. For example, `super_options={"cookieless_mode": True}` wins over an event's `$cookieless_mode: False`. When you move a default to options, move the per-event overrides of that key to options too. diff --git a/posthog/async_client.py b/posthog/async_client.py index be365b83c..4ea984db9 100644 --- a/posthog/async_client.py +++ b/posthog/async_client.py @@ -105,6 +105,8 @@ clean, _drop_invalid_distinct_id, _drop_invalid_event_name, + _log_before_send_bad_return, + _log_before_send_error, system_context, ) from .version import VERSION @@ -524,18 +526,20 @@ async def _run_before_send(self, msg: dict[str, Any]) -> Optional[dict[str, Any] return msg original_uuid = msg["uuid"] + event_name = msg.get("event") try: result = await _invoke_callback(self.before_send, msg) if result is None: self.log.debug("event dropped by before_send callback") return None if not isinstance(result, dict): - raise TypeError("before_send must return a dict or None") + _log_before_send_bad_return(self.log, event_name, result) + return None processed = clean(result) processed["uuid"] = original_uuid return processed except Exception as error: - self.log.error("Error in before_send callback (%s)", type(error).__name__) + _log_before_send_error(self.log, event_name, error) return None def _event_defaults( diff --git a/posthog/capture_send.py b/posthog/capture_send.py index 90c55b54a..4d0e01d91 100644 --- a/posthog/capture_send.py +++ b/posthog/capture_send.py @@ -44,7 +44,7 @@ DatetimeSerializer, USER_AGENT, APIError, - _get_session, + _get_capture_session, normalize_host, ) from posthog.utils import _uuid7, remove_trailing_slash @@ -376,7 +376,7 @@ def _post_v1( headers["Content-Encoding"] = encoding log.debug("capture v1 POST %s attempt=%s request_id=%s", url, attempt, request_id) - http = session or _get_session() + http = session or _get_capture_session() for _ in range(_MAX_REDIRECTS + 1): res = http.post( url, data=body, headers=headers, timeout=timeout, allow_redirects=False diff --git a/posthog/client.py b/posthog/client.py index c0393738d..51188966e 100644 --- a/posthog/client.py +++ b/posthog/client.py @@ -142,6 +142,8 @@ _is_personal_api_key, _drop_invalid_distinct_id, _drop_invalid_event_name, + _log_before_send_bad_return, + _log_before_send_error, guess_timezone as guess_timezone, system_context, ) @@ -2601,16 +2603,18 @@ def _enqueue( msg = clean(msg) if self.before_send: + event_name = msg.get("event") try: modified_msg = self.before_send(msg) if modified_msg is None: self.log.debug("Event dropped by before_send callback") return None if not isinstance(modified_msg, dict): - raise TypeError("before_send must return a dict or None") + _log_before_send_bad_return(self.log, event_name, modified_msg) + return None msg = clean(modified_msg) except Exception as e: - self.log.exception(f"Error in before_send callback: {e}") + _log_before_send_error(self.log, event_name, e) return None # Re-normalized after before_send, which may have replaced or removed diff --git a/posthog/request.py b/posthog/request.py index ef73c7212..646a048a9 100644 --- a/posthog/request.py +++ b/posthog/request.py @@ -73,7 +73,7 @@ def init_poolmanager(self, *args, **kwargs): def _build_session(socket_options: Optional[SocketOptions] = None) -> requests.Session: - """Build a session for general requests (batch, remote config, etc.).""" + """Build a session for general requests (remote config, flag definitions, etc.).""" adapter = HTTPAdapterWithSocketOptions( max_retries=Retry( total=2, @@ -87,13 +87,13 @@ def _build_session(socket_options: Optional[SocketOptions] = None) -> requests.S return session -def _build_flags_session( +def _build_no_retry_session( socket_options: Optional[SocketOptions] = None, ) -> requests.Session: - """Build a session for feature flag requests. + """Build a session whose adapter never retries; ``flags()`` and capture own retries. - /flags retries are handled explicitly in ``flags()`` so that only - transport failures and contract-defined transient HTTP responses are retried. + Capture needs a fresh ``PostHog-Request-Timestamp`` on every physical attempt, + because capture uses it to correct clock skew. """ adapter = HTTPAdapterWithSocketOptions( max_retries=Retry(total=0, connect=0, read=0, status=0), @@ -105,7 +105,8 @@ def _build_flags_session( _session = _build_session() -_flags_session = _build_flags_session() +_flags_session = _build_no_retry_session() +_capture_session = _build_no_retry_session() _socket_options: Optional[SocketOptions] = None _pooling_enabled = True @@ -119,7 +120,13 @@ def _get_session() -> requests.Session: def _get_flags_session() -> requests.Session: if _pooling_enabled: return _flags_session - return _build_flags_session(_socket_options) + return _build_no_retry_session(_socket_options) + + +def _get_capture_session() -> requests.Session: + if _pooling_enabled: + return _capture_session + return _build_no_retry_session(_socket_options) def reset_sessions() -> None: @@ -127,13 +134,16 @@ def reset_sessions() -> None: Reset the global sessions. This should be called after a fork to ensure that the child process does not use the parent's connection pool. """ - global _session, _flags_session + global _session, _flags_session, _capture_session if _session: _session.close() if _flags_session: _flags_session.close() + if _capture_session: + _capture_session.close() _session = _build_session(_socket_options) - _flags_session = _build_flags_session(_socket_options) + _flags_session = _build_no_retry_session(_socket_options) + _capture_session = _build_no_retry_session(_socket_options) def set_socket_options(socket_options: Optional[SocketOptions]) -> None: @@ -151,12 +161,13 @@ def set_socket_options(socket_options: Optional[SocketOptions]) -> None: from posthog import set_socket_options set_socket_options([(socket.SOL_SOCKET, socket.SO_KEEPALIVE, 1)]) """ - global _session, _flags_session, _socket_options + global _session, _flags_session, _capture_session, _socket_options if socket_options == _socket_options: return _socket_options = socket_options _session = _build_session(socket_options) - _flags_session = _build_flags_session(socket_options) + _flags_session = _build_no_retry_session(socket_options) + _capture_session = _build_no_retry_session(socket_options) def enable_keep_alive() -> None: @@ -440,4 +451,10 @@ def default(self, obj: Any): return json.JSONEncoder.default(self, obj) def encode(self, o: Any) -> str: + # A strict encode fails only on a non-finite float, so finite events skip the copy. + if not self.allow_nan: + try: + return super().encode(o) + except ValueError: + pass return super().encode(_replace_non_finite_floats(o)) diff --git a/posthog/test/logging_helpers.py b/posthog/test/logging_helpers.py index ae1ca6fdc..629963764 100644 --- a/posthog/test/logging_helpers.py +++ b/posthog/test/logging_helpers.py @@ -1,7 +1,7 @@ import io import logging from contextlib import contextmanager -from typing import Iterator +from typing import Iterator, Sequence from posthog._logging import _POSTHOG_LOGGER_NAME @@ -25,3 +25,18 @@ def capture_message_only_logs(level: int = logging.DEBUG) -> Iterator[io.StringI handler.close() logger.setLevel(previous_level) logger.propagate = previous_propagate + + +def assert_before_send_failure_logged( + records: Sequence[logging.LogRecord], event_name: str, error_type: str +) -> None: + errors = [r for r in records if r.levelno >= logging.ERROR] + assert [r.getMessage() for r in errors] == [ + f"[PostHog] Error in before_send callback for event {event_name} " + f"({error_type}), dropping the event" + ] + assert errors[0].exc_info is None + tracebacks = [r for r in records if r.exc_info] + assert [(r.levelno, r.exc_info[0].__name__) for r in tracebacks] == [ + (logging.DEBUG, error_type) + ] diff --git a/posthog/test/test_async_client.py b/posthog/test/test_async_client.py index 5aa79fd09..5f3cc79c4 100644 --- a/posthog/test/test_async_client.py +++ b/posthog/test/test_async_client.py @@ -28,6 +28,7 @@ ) from posthog.request import APIError from posthog.test.capture_helpers import patch_async_capture_send +from posthog.test.logging_helpers import assert_before_send_failure_logged @pytest.mark.asyncio @@ -294,7 +295,7 @@ def before_send(event): @pytest.mark.asyncio -async def test_capture_drops_event_when_before_send_raises(): +async def test_capture_drops_event_when_before_send_raises(caplog): async def before_send(_event): raise RuntimeError("callback failed") @@ -302,11 +303,29 @@ async def before_send(_event): async with AsyncPosthog( "test-key", before_send=before_send, flush_interval=0.01 ) as client: - accepted_uuid = client.capture("event", distinct_id="user-1") - await client.flush(timeout_seconds=1) + with caplog.at_level(logging.DEBUG, logger="posthog"): + accepted_uuid = client.capture("event", distinct_id="user-1") + await client.flush(timeout_seconds=1) assert accepted_uuid is not None send_batch.assert_not_awaited() + assert_before_send_failure_logged(caplog.records, "event", "RuntimeError") + + +@pytest.mark.asyncio +async def test_capture_drops_event_when_before_send_returns_non_dict(caplog): + with patch_async_capture_send(new=mock.AsyncMock()) as send_batch: + async with AsyncPosthog( + "test-key", before_send=lambda _event: "invalid", flush_interval=0.01 + ) as client: + with caplog.at_level(logging.ERROR, logger="posthog"): + client.capture("event", distinct_id="user-1") + await client.flush(timeout_seconds=1) + + send_batch.assert_not_awaited() + assert [r.getMessage() for r in caplog.records] == [ + "[PostHog] before_send must return a dict or None, not str, dropping event event" + ] @pytest.mark.asyncio diff --git a/posthog/test/test_before_send.py b/posthog/test/test_before_send.py index acdddb87d..e2cda0a76 100644 --- a/posthog/test/test_before_send.py +++ b/posthog/test/test_before_send.py @@ -7,6 +7,7 @@ import posthog from posthog.client import Client +from posthog.test.logging_helpers import assert_before_send_failure_logged from posthog.test.test_utils import FAKE_TEST_API_KEY from posthog.test.capture_helpers import ( patch_capture_send, @@ -172,14 +173,16 @@ def buggy_before_send(event): "_normalize_event_uuid", wraps=client._normalize_event_uuid, ) as normalize_uuid, - self.assertLogs("posthog", level="ERROR") as logs, + self.assertLogs("posthog", level="DEBUG") as logs, ): msg_uuid = client.capture("robust_event", distinct_id="user1") self.assertIsNone(msg_uuid) mock_post.assert_not_called() normalize_uuid.assert_called_once() - self.assertIn("Error in before_send callback: Oops!", logs.output[0]) + assert_before_send_failure_logged( + logs.records, "robust_event", "ValueError" + ) def test_before_send_callback_exception_does_not_enqueue_mutated_event(self): def buggy_before_send(event): @@ -229,20 +232,22 @@ def add_unsupported_value(event): self.assertIsNone(sent_event["properties"]["marker"]) def test_before_send_callback_non_dict_output_drops_event(self): - with ( - patch_capture_send("client") as mock_post, - mock.patch("posthog.client.Client.log.exception") as mock_log, - ): + with patch_capture_send("client") as mock_post: client = Client( FAKE_TEST_API_KEY, before_send=lambda _event: "invalid", sync_mode=True, ) - self.assertIsNone(client.capture("original", distinct_id="user1")) + with self.assertLogs("posthog", level="ERROR") as logs: + self.assertIsNone(client.capture("original", distinct_id="user1")) mock_post.assert_not_called() - self.assertIn( - "before_send must return a dict or None", mock_log.call_args.args[0] + self.assertEqual( + logs.output, + [ + "ERROR:posthog:[PostHog] before_send must return a dict or None, " + "not str, dropping event original" + ], ) @parameterized.expand( diff --git a/posthog/test/test_capture_invariants.py b/posthog/test/test_capture_invariants.py index 48f933bee..5c931cde4 100644 --- a/posthog/test/test_capture_invariants.py +++ b/posthog/test/test_capture_invariants.py @@ -47,7 +47,7 @@ def post(url, data=None, **kwargs): session = mock.Mock() session.post.side_effect = post - return mock.patch("posthog.capture_send._get_session", return_value=session) + return mock.patch("posthog.capture_send._get_capture_session", return_value=session) def _send_sync(method_name: str, before_send) -> list[tuple[str, list[dict]]]: diff --git a/posthog/test/test_capture_send.py b/posthog/test/test_capture_send.py index d3b7b17ab..a50d62c7e 100644 --- a/posthog/test/test_capture_send.py +++ b/posthog/test/test_capture_send.py @@ -7,6 +7,8 @@ import zstandard +from requests.adapters import HTTPAdapter + from parameterized import parameterized from posthog import capture_send @@ -732,6 +734,33 @@ def test_transport_error_exhausted_raises_capture_error(self) -> None: self.assertEqual(ctx.exception.attempts, 2) self.assertIsInstance(ctx.exception.__cause__, ConnectionError) + def test_refused_connection_is_retried_by_the_sdk_not_the_http_adapter( + self, + ) -> None: + # Each physical try must be its own SDK attempt, so capture gets a fresh request timestamp. + sent_attempts = [] + real_send = HTTPAdapter.send + + def record_send(adapter, request, **kwargs): + sent_attempts.append(request.headers[_HEADER_ATTEMPT]) + return real_send(adapter, request, **kwargs) + + with ( + mock.patch.object(HTTPAdapter, "send", record_send), + mock.patch( + "urllib3.util.connection.create_connection", + side_effect=ConnectionRefusedError, + ) as connect, + self.assertRaises(CaptureError) as ctx, + ): + _send_v1_batch( + "phc_key", "https://app.posthog.com", [_msg("u-1")], max_retries=2 + ) + + self.assertEqual(sent_attempts, ["1", "2", "3"]) + self.assertEqual(connect.call_count, 3) + self.assertEqual(ctx.exception.attempts, 3) + def test_negative_max_retries_still_attempts_delivery_once(self) -> None: stub = _PostV1Stub([_results_response({"u-1": "ok"})]) diff --git a/posthog/test/test_client_fork.py b/posthog/test/test_client_fork.py index 442322eb5..8b579cde0 100644 --- a/posthog/test/test_client_fork.py +++ b/posthog/test/test_client_fork.py @@ -437,6 +437,7 @@ def test_register_at_fork_reinitializes_poller_and_sessions_in_child_process(sel old_poller = client.poller session_before = posthog.request._get_session() flags_session_before = posthog.request._get_flags_session() + capture_session_before = posthog.request._get_capture_session() def child_probe(): poller_ok = False @@ -456,8 +457,11 @@ def child_probe(): session_after = posthog.request._get_session() flags_session_after = posthog.request._get_flags_session() - sessions_ok = (session_after is not session_before) and ( - flags_session_after is not flags_session_before + capture_session_after = posthog.request._get_capture_session() + sessions_ok = ( + session_after is not session_before + and flags_session_after is not flags_session_before + and capture_session_after is not capture_session_before ) if poller_ok and sessions_ok: diff --git a/posthog/test/test_code_variables.py b/posthog/test/test_code_variables.py index 4e8fab36a..30d86d243 100644 --- a/posthog/test/test_code_variables.py +++ b/posthog/test/test_code_variables.py @@ -116,7 +116,7 @@ def extract( from posthog.test.capture_helpers import offline_v1_post -posthog.request._session.post = offline_v1_post +posthog.request._capture_session.post = offline_v1_post def print_event(event): diff --git a/posthog/test/test_exception_capture.py b/posthog/test/test_exception_capture.py index cf7272709..f5d0f1a30 100644 --- a/posthog/test/test_exception_capture.py +++ b/posthog/test/test_exception_capture.py @@ -291,7 +291,7 @@ def test_excepthook(tmpdir): import posthog.request from posthog.test.capture_helpers import offline_v1_post - posthog.request._session.post = offline_v1_post + posthog.request._capture_session.post = offline_v1_post posthog = Posthog('phc_x', host='https://eu.i.posthog.com', enable_exception_autocapture=True, debug=True, on_error=lambda e, batch: print('error handling batch: ', e, batch)) # frame_value = "LOL" diff --git a/posthog/test/test_request.py b/posthog/test/test_request.py index 1a253e8a5..851bd8a0d 100644 --- a/posthog/test/test_request.py +++ b/posthog/test/test_request.py @@ -418,10 +418,13 @@ def test_routing_to_custom_host(host, expected): def test_enable_keep_alive_sets_socket_options(): try: enable_keep_alive() - from posthog.request import _session - - adapter = _session.get_adapter("https://example.com") - assert adapter.socket_options == KEEP_ALIVE_SOCKET_OPTIONS + for session in ( + request_module._get_session(), + request_module._get_flags_session(), + request_module._get_capture_session(), + ): + adapter = session.get_adapter("https://example.com") + assert adapter.socket_options == KEEP_ALIVE_SOCKET_OPTIONS finally: set_socket_options(None) @@ -462,12 +465,14 @@ def test_set_socket_options_is_idempotent(): class TestFlagsSession(unittest.TestCase): """Tests for flags session configuration.""" - def test_flags_session_disables_adapter_retries(self): - """HTTP adapter retries are disabled; flags() handles bounded retries.""" - from posthog.request import _build_flags_session - - session = _build_flags_session() - adapter = session.get_adapter("https://test.posthog.com") + @parameterized.expand( + [ + ("flags", request_module._get_flags_session), + ("capture", request_module._get_capture_session), + ] + ) + def test_session_disables_adapter_retries(self, _name, get_session): + adapter = get_session().get_adapter("https://test.posthog.com") retry = adapter.max_retries self.assertEqual(retry.total, 0) @@ -697,6 +702,33 @@ def test_post_serializes_non_finite_floats_as_null(): assert props["ok"] == 1.5 -def test_datetime_serializer_keeps_finite_values(): - body = {"n": 1.5, "s": "x", "b": True, "i": 3, "none": None} - assert json.loads(json.dumps(body, cls=DatetimeSerializer)) == body +@pytest.mark.parametrize("allow_nan", [False, True]) +@pytest.mark.parametrize( + "body, expected", + [ + ( + {"n": 1.5, "s": "x", "b": True, "none": None, "t": (1, 2.5)}, + '{"n": 1.5, "s": "x", "b": true, "none": null, "t": [1, 2.5]}', + ), + ( + {"n": float("nan"), "l": [float("inf"), (float("-inf"), 2.5)]}, + '{"n": null, "l": [null, [null, 2.5]]}', + ), + ], +) +def test_datetime_serializer_writes_non_finite_floats_as_null( + body, expected, allow_nan +): + assert json.dumps(body, cls=DatetimeSerializer, allow_nan=allow_nan) == expected + + +def test_datetime_serializer_copies_only_events_with_non_finite_floats(): + with mock.patch.object( + request_module, + "_replace_non_finite_floats", + wraps=request_module._replace_non_finite_floats, + ) as copy: + json.dumps({"n": [1.5]}, cls=DatetimeSerializer, allow_nan=False) + copy.assert_not_called() + json.dumps({"n": [float("nan")]}, cls=DatetimeSerializer, allow_nan=False) + copy.assert_called() diff --git a/posthog/test/test_server_payload_snapshots.py b/posthog/test/test_server_payload_snapshots.py index 71f437edd..b0bbb0528 100644 --- a/posthog/test/test_server_payload_snapshots.py +++ b/posthog/test/test_server_payload_snapshots.py @@ -117,7 +117,7 @@ def _event_family_request(): with ( freeze_time(_FIXED_TIME), - mock.patch("posthog.capture_send._get_session", return_value=session), + mock.patch("posthog.capture_send._get_capture_session", return_value=session), mock.patch("posthog.client.system_context", return_value=_RUNTIME_CONTEXT), ): client = Client( @@ -182,7 +182,7 @@ def _exception_request(): with ( freeze_time(_FIXED_TIME), - mock.patch("posthog.capture_send._get_session", return_value=session), + mock.patch("posthog.capture_send._get_capture_session", return_value=session), mock.patch("posthog.client.system_context", return_value=_RUNTIME_CONTEXT), mock.patch("posthog.client._get_current_otel_span_properties", return_value={}), ): diff --git a/posthog/test/test_utils.py b/posthog/test/test_utils.py index d73525ee2..9863cf4c0 100644 --- a/posthog/test/test_utils.py +++ b/posthog/test/test_utils.py @@ -391,6 +391,27 @@ def test_drop_invalid_event_name_logs_each_reason_once(self): mock.call(message, "empty"), ] + def test_before_send_logs_name_the_event_and_never_the_exception_message(self): + logger = mock.Mock() + error = ValueError("secret@example.com") + + utils._log_before_send_error(logger, "signup", error) + utils._log_before_send_bad_return(logger, "signup", ["not", "a", "dict"]) + + assert logger.method_calls == [ + mock.call.error( + "Error in before_send callback for event %s (%s), dropping the event", + "signup", + "ValueError", + ), + mock.call.debug("before_send callback traceback", exc_info=error), + mock.call.error( + "before_send must return a dict or None, not %s, dropping event %s", + "list", + "signup", + ), + ] + def test_drop_invalid_distinct_id_logs_each_reason_once(self): logger = mock.Mock() with mock.patch.object(utils, "_warned_reasons", set()): diff --git a/posthog/utils.py b/posthog/utils.py index 4f1d25517..dbb94cbf3 100644 --- a/posthog/utils.py +++ b/posthog/utils.py @@ -183,6 +183,28 @@ def _drop_invalid_event_name(logger: logging.Logger, msg: dict) -> bool: return True +def _log_before_send_error( + logger: logging.Logger, event_name: Any, error: Exception +) -> None: + """Log a raising before_send hook without its message, which can hold event data.""" + logger.error( + "Error in before_send callback for event %s (%s), dropping the event", + event_name, + type(error).__name__, + ) + logger.debug("before_send callback traceback", exc_info=error) + + +def _log_before_send_bad_return( + logger: logging.Logger, event_name: Any, result: Any +) -> None: + logger.error( + "before_send must return a dict or None, not %s, dropping event %s", + type(result).__name__, + event_name, + ) + + def _drop_invalid_distinct_id(logger: logging.Logger, msg: dict) -> bool: """True when `msg` has no string distinct_id; logs once per reason.