diff --git a/.cursor/BUGBOT.md b/.cursor/BUGBOT.md index 8339447..da4eb76 100644 --- a/.cursor/BUGBOT.md +++ b/.cursor/BUGBOT.md @@ -4,6 +4,22 @@ - When adding a new instrumentation, the README must be updated to document the new instrumentation. +## Logging Levels + +The SDK's default log level is `info` (see `drift/core/logger.py`). Customers initializing with `TuskDrift.initialize(env=...)` and no logger overrides will see every `logger.info(...)` line in their application output. + +**Rules:** + +1. **Per-call / per-request / per-query log lines MUST use `logger.debug(...)`, never `logger.info(...)`.** This includes anything inside a patched function body that runs on every invocation (e.g. `patched_connect`, middleware `__call__`, request hooks, cursor wrappers). One INFO line per DB connect or HTTP request floods customer logs and looks like a bug to them. + +2. **"X instrumented" startup lines MUST be `logger.debug(...)`.** The convention (see `drift/instrumentation/redis/instrumentation.py` and the sync paths in `drift/instrumentation/psycopg/instrumentation.py`) is debug. Even though these fire once per process, they appear in every customer's startup logs and read as internal SDK noise. Do not include the patched function's repr (`module.connect is now: ...`) at any level — it leaks implementation detail and confuses customers. + +3. **`logger.info(...)` is reserved for events the customer genuinely benefits from seeing once:** "App marked as ready", circuit-breaker state transitions, Rust-core enable/disable at startup, mode-change events. If the line can fire more than ~once per process lifetime in normal operation, it must be `debug`. + +4. **When adding a sibling instrumentation (e.g. psycopg2 alongside psycopg3), match the existing level conventions across both.** The psycopg2/psycopg3 split caused exactly this bug — psycopg3 used `debug` for "RECORD mode: Connected", psycopg2 used `info`, and customers saw 4 noise lines per connect. + +5. **Do not log raw header dicts, query args, or connection arguments at INFO** even once — these can be high-cardinality and contain sensitive values. Use `debug` and prefer logging only the keys, not values. + ## REPLAY Mode: Context Ordering and OUTPUT_VALUE on Inbound Spans When implementing or modifying a REPLAY mode handler (e.g., `_handle_replay_request`) in any framework instrumentation (Django, FastAPI, Flask, WSGI, etc.): diff --git a/drift/instrumentation/aiohttp/instrumentation.py b/drift/instrumentation/aiohttp/instrumentation.py index a3204be..c9d7168 100644 --- a/drift/instrumentation/aiohttp/instrumentation.py +++ b/drift/instrumentation/aiohttp/instrumentation.py @@ -203,7 +203,7 @@ async def original_call(): # Apply patch module.ClientSession._request = patched_request - logger.info("aiohttp.ClientSession._request instrumented") + logger.debug("aiohttp.ClientSession._request instrumented") async def _handle_replay_request( self, diff --git a/drift/instrumentation/django/middleware.py b/drift/instrumentation/django/middleware.py index b534f8d..27c4d17 100644 --- a/drift/instrumentation/django/middleware.py +++ b/drift/instrumentation/django/middleware.py @@ -97,10 +97,10 @@ def _handle_replay_request(self, request: HttpRequest, sdk) -> HttpResponse: # Extract trace ID from headers (case-insensitive lookup) # Django stores headers in request.META headers_lower = {k.lower(): v for k, v in request.META.items() if k.startswith("HTTP_")} - logger.info(f"[DJANGO_MIDDLEWARE] REPLAY mode, headers: {list(headers_lower.keys())}") + logger.debug(f"[DJANGO_MIDDLEWARE] REPLAY mode, headers: {list(headers_lower.keys())}") # Convert HTTP_X_TD_TRACE_ID -> x-td-trace-id replay_trace_id = headers_lower.get("http_x_td_trace_id") - logger.info(f"[DJANGO_MIDDLEWARE] replay_trace_id from header: {replay_trace_id}") + logger.debug(f"[DJANGO_MIDDLEWARE] replay_trace_id from header: {replay_trace_id}") if not replay_trace_id: # No trace context in REPLAY mode; proceed without span diff --git a/drift/instrumentation/grpc/instrumentation.py b/drift/instrumentation/grpc/instrumentation.py index 090961a..6cfcd81 100644 --- a/drift/instrumentation/grpc/instrumentation.py +++ b/drift/instrumentation/grpc/instrumentation.py @@ -94,7 +94,7 @@ def patch(self, module: Any) -> None: # to return instrumented channels self._patch_channel_factories(module) - logger.info("grpc module instrumented") + logger.debug("grpc module instrumented") def _patch_channel_factories(self, module: Any) -> None: """Patch channel factory functions to instrument created channels.""" diff --git a/drift/instrumentation/httpx/instrumentation.py b/drift/instrumentation/httpx/instrumentation.py index e66e561..0da9bf5 100644 --- a/drift/instrumentation/httpx/instrumentation.py +++ b/drift/instrumentation/httpx/instrumentation.py @@ -325,7 +325,7 @@ def original_call(): # Apply patch module.Client.send = patched_send - logger.info("httpx.Client.send instrumented") + logger.debug("httpx.Client.send instrumented") def _handle_replay_send_sync( self, @@ -518,7 +518,7 @@ async def original_call(): # Apply patch module.AsyncClient.send = patched_send - logger.info("httpx.AsyncClient.send instrumented") + logger.debug("httpx.AsyncClient.send instrumented") async def _handle_replay_send_async( self, diff --git a/drift/instrumentation/psycopg/instrumentation.py b/drift/instrumentation/psycopg/instrumentation.py index c4423d8..a12efed 100644 --- a/drift/instrumentation/psycopg/instrumentation.py +++ b/drift/instrumentation/psycopg/instrumentation.py @@ -90,10 +90,10 @@ def patched_connect(*args, **kwargs): # Set server cursor factory on the connection for named cursors if server_cursor_factory: connection.server_cursor_factory = server_cursor_factory - logger.info("[PATCHED_CONNECT] REPLAY mode: Successfully connected to database (psycopg3)") + logger.debug("[PATCHED_CONNECT] REPLAY mode: Successfully connected to database (psycopg3)") return connection except Exception as e: - logger.info( + logger.debug( f"[PATCHED_CONNECT] REPLAY mode: Database connection failed ({e}), using mock connection (psycopg3)" ) # Return mock connection that doesn't require a real database @@ -220,12 +220,12 @@ async def patched_async_connect(conninfo="", **kwargs): if user_row_factory is not None: kwargs["row_factory"] = user_row_factory connection = await original_async_connect(conninfo, **kwargs) - logger.info( + logger.debug( "[PATCHED_ASYNC_CONNECT] REPLAY mode: Successfully connected to database (psycopg3 async)" ) return connection except Exception as e: - logger.info( + logger.debug( f"[PATCHED_ASYNC_CONNECT] REPLAY mode: Database connection failed ({e}), using mock async connection" ) # Import mock async connection @@ -245,7 +245,7 @@ async def patched_async_connect(conninfo="", **kwargs): AsyncConnection.connect = classmethod( lambda cls, conninfo="", **kwargs: patched_async_connect(conninfo, **kwargs) ) - logger.info("psycopg.AsyncConnection.connect instrumented") + logger.debug("psycopg.AsyncConnection.connect instrumented") # Also patch AsyncConnectionPool to inject cursor_factory self._patch_async_connection_pool(module) @@ -283,7 +283,7 @@ def patched_init(pool_self, conninfo="", **kwargs): return original_init(pool_self, conninfo, **kwargs) AsyncConnectionPool.__init__ = patched_init - logger.info("psycopg_pool.AsyncConnectionPool.__init__ instrumented") + logger.debug("psycopg_pool.AsyncConnectionPool.__init__ instrumented") def _create_async_cursor_factory(self, sdk: TuskDrift, base_factory=None): """Create an async cursor factory that wraps async cursors with instrumentation. diff --git a/drift/instrumentation/psycopg2/instrumentation.py b/drift/instrumentation/psycopg2/instrumentation.py index 51847ff..095a40e 100644 --- a/drift/instrumentation/psycopg2/instrumentation.py +++ b/drift/instrumentation/psycopg2/instrumentation.py @@ -390,7 +390,7 @@ def _unwrap_connection(conn_or_curs: Any) -> Any: psycopg2.extras.register_default_jsonb = lambda *args, **kwargs: None if original_register_uuid: psycopg2.extras.register_uuid = lambda *args, **kwargs: None - logger.info("[PSYCOPG2_REPLAY] Patched psycopg2.extras register functions to be no-ops") + logger.debug("[PSYCOPG2_REPLAY] Patched psycopg2.extras register functions to be no-ops") else: # In RECORD mode, unwrap InstrumentedConnection before calling original if original_register_default_json: @@ -422,16 +422,16 @@ def patched_register_uuid(oids: Any = None, conn_or_curs: Any = None) -> Any: psycopg2.extras.register_uuid = patched_register_uuid - logger.info("[PSYCOPG2] Patched psycopg2.extras register functions to unwrap InstrumentedConnection") + logger.debug("[PSYCOPG2] Patched psycopg2.extras register functions to unwrap InstrumentedConnection") except Exception as e: logger.warning(f"[PSYCOPG2] Failed to patch psycopg2.extras: {e}") def patched_connect(*args, **kwargs): """Patched psycopg2.connect method.""" sdk = TuskDrift.get_instance() - logger.info("[PATCHED_CONNECT] psycopg2.connect() called") - logger.info(f"[PATCHED_CONNECT] mode: {sdk.mode}") - logger.info(f"[PATCHED_CONNECT] app_ready: {sdk.app_ready}") + logger.debug("[PATCHED_CONNECT] psycopg2.connect() called") + logger.debug(f"[PATCHED_CONNECT] mode: {sdk.mode}") + logger.debug(f"[PATCHED_CONNECT] app_ready: {sdk.app_ready}") logger.debug(f"[PATCHED_CONNECT] args: {args[:2] if args else 'none'}") # Pass through if SDK is disabled or original connect is missing @@ -446,11 +446,11 @@ def patched_connect(*args, **kwargs): try: logger.debug("[PATCHED_CONNECT] REPLAY mode: Attempting real DB connection...") connection = original_connect(*args, **kwargs) - logger.info("[PATCHED_CONNECT] REPLAY mode: Successfully connected to real database") + logger.debug("[PATCHED_CONNECT] REPLAY mode: Successfully connected to real database") # Wrap connection to intercept cursor() calls return InstrumentedConnection(connection, instrumentation, sdk) except Exception as e: - logger.info( + logger.debug( f"[PATCHED_CONNECT] REPLAY mode: Database connection failed ({e}), using mock connection" ) # Return mock connection that doesn't require a real database @@ -460,19 +460,19 @@ def patched_connect(*args, **kwargs): # In RECORD mode, always require real connection logger.debug("[PATCHED_CONNECT] RECORD mode: Connecting to database...") connection = original_connect(*args, **kwargs) - logger.info("[PATCHED_CONNECT] RECORD mode: Connected to database successfully") + logger.debug("[PATCHED_CONNECT] RECORD mode: Connected to database successfully") # Wrap connection to intercept cursor() calls return InstrumentedConnection(connection, instrumentation, sdk) # Apply patch module.connect = patched_connect # type: ignore[attr-defined] - logger.info(f"psycopg2.connect instrumented. module.connect is now: {getattr(module, 'connect', None)}") + logger.debug("psycopg2.connect instrumented") # Also verify it's actually patched import psycopg2 if psycopg2.connect == patched_connect: - logger.info("[VERIFY] psycopg2.connect successfully patched!") + logger.debug("[VERIFY] psycopg2.connect successfully patched!") else: logger.error( f"[VERIFY] psycopg2.connect NOT patched! psycopg2.connect={psycopg2.connect}, patched_connect={patched_connect}" diff --git a/drift/instrumentation/requests/instrumentation.py b/drift/instrumentation/requests/instrumentation.py index 1d54db0..eeb34ed 100644 --- a/drift/instrumentation/requests/instrumentation.py +++ b/drift/instrumentation/requests/instrumentation.py @@ -154,7 +154,7 @@ def original_call(): # Apply patch module.Session.send = patched_send - logger.info("requests.Session.send instrumented") + logger.debug("requests.Session.send instrumented") def _get_default_response(self, url: str) -> Any: """Return default response for background requests in REPLAY mode. diff --git a/drift/instrumentation/urllib/instrumentation.py b/drift/instrumentation/urllib/instrumentation.py index a0ea610..26e1bc4 100644 --- a/drift/instrumentation/urllib/instrumentation.py +++ b/drift/instrumentation/urllib/instrumentation.py @@ -378,7 +378,7 @@ def original_call(): # Apply patch module.OpenerDirector.open = patched_open - logger.info("urllib.request.OpenerDirector.open instrumented") + logger.debug("urllib.request.OpenerDirector.open instrumented") def _extract_request_info(self, fullurl: Any, data: bytes | None) -> dict[str, Any]: """Extract request information from urlopen arguments. diff --git a/drift/instrumentation/urllib3/instrumentation.py b/drift/instrumentation/urllib3/instrumentation.py index 9341d28..5f1a155 100644 --- a/drift/instrumentation/urllib3/instrumentation.py +++ b/drift/instrumentation/urllib3/instrumentation.py @@ -218,7 +218,7 @@ def original_call(): calling_library_context.reset(context_token) module.PoolManager.urlopen = patched_urlopen - logger.info("urllib3.PoolManager.urlopen instrumented") + logger.debug("urllib3.PoolManager.urlopen instrumented") def _patch_connection_pool(self, module: Any) -> None: """Patch urllib3.HTTPConnectionPool.urlopen for direct pool usage.""" @@ -363,7 +363,7 @@ def original_call(): calling_library_context.reset(context_token) module.HTTPConnectionPool.urlopen = patched_urlopen - logger.info("urllib3.HTTPConnectionPool.urlopen instrumented") + logger.debug("urllib3.HTTPConnectionPool.urlopen instrumented") def _get_default_response(self, urllib3_module: Any, url: str) -> Any: """Return default response for background requests in REPLAY mode.