Skip to content

Commit 600aa8d

Browse files
apcha-oaiapcha-oai
authored
fix: keep Python SDK diagnostics metadata-only (#3685)
Troubleshooting logs should help identify request failures without retaining the data applications send or receive. This change keeps request, retry, status, and WebSocket size information while limiting SDK diagnostics to metadata. Request delivery, response parsing, and error handling are unchanged. The SDK logging setting now controls SDK logs without changing application-configured HTTP transport logging.
1 parent 689538d commit 600aa8d

10 files changed

Lines changed: 470 additions & 74 deletions

File tree

‎src/openai/_base_client.py‎

Lines changed: 22 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -62,7 +62,7 @@
6262
not_given,
6363
)
6464
from ._utils import SensitiveHeadersFilter, is_dict, is_list, asyncify, is_given, lru_cache, is_mapping
65-
from ._compat import PYDANTIC_V1, model_copy, model_dump
65+
from ._compat import PYDANTIC_V1, model_copy
6666
from ._httpx2 import (
6767
status_exceptions,
6868
timeout_exceptions,
@@ -104,6 +104,7 @@
104104
APIResponseValidationError,
105105
)
106106
from ._utils._json import openapi_dumps
107+
from ._utils._logs import get_http_method_for_logging
107108
from ._legacy_response import LegacyAPIResponse
108109

109110
log: logging.Logger = logging.getLogger(__name__)
@@ -519,20 +520,12 @@ def _build_request(
519520
*,
520521
retries_taken: int = 0,
521522
) -> httpx2.Request:
522-
if log.isEnabledFor(logging.DEBUG):
523-
log.debug(
524-
"Request options: %s",
525-
model_dump(
526-
options,
527-
exclude_unset=True,
528-
# Pydantic v1 can't dump every type we support in content, so we exclude it for now.
529-
exclude={
530-
"content",
531-
}
532-
if PYDANTIC_V1
533-
else {},
534-
),
535-
)
523+
# Request bodies, files, URLs, and custom options can contain private data.
524+
log.debug(
525+
"Building HTTP request: method=%s retries_taken=%i",
526+
get_http_method_for_logging(options.method),
527+
retries_taken,
528+
)
536529
kwargs: dict[str, Any] = {}
537530

538531
json_data = options.json_data
@@ -1079,7 +1072,7 @@ def request(
10791072
if options.follow_redirects is not None:
10801073
kwargs["follow_redirects"] = options.follow_redirects
10811074

1082-
log.debug("Sending HTTP Request: %s %s", request.method, request.url)
1075+
log.debug("Sending HTTP Request: %s", get_http_method_for_logging(request.method))
10831076

10841077
response = None
10851078
try:
@@ -1089,7 +1082,7 @@ def request(
10891082
**kwargs,
10901083
)
10911084
except timeout_exceptions() as err:
1092-
log.debug("Encountered a timeout exception", exc_info=True)
1085+
log.debug("Encountered a timeout exception: %s", type(err).__name__)
10931086

10941087
if remaining_retries > 0:
10951088
self._sleep_for_retry(
@@ -1106,7 +1099,7 @@ def request(
11061099
# Propagate OpenAIErrors as-is, without retrying or wrapping in APIConnectionError
11071100
raise err
11081101
except Exception as err:
1109-
log.debug("Encountered Exception", exc_info=True)
1102+
log.debug("Encountered exception: %s", type(err).__name__)
11101103

11111104
if remaining_retries > 0:
11121105
self._sleep_for_retry(
@@ -1121,19 +1114,16 @@ def request(
11211114
raise APIConnectionError(request=request) from err
11221115

11231116
log.debug(
1124-
'HTTP Response: %s %s "%i %s" %s',
1125-
request.method,
1126-
request.url,
1117+
"HTTP Response: %s %i",
1118+
get_http_method_for_logging(request.method),
11271119
response.status_code,
1128-
response.reason_phrase,
1129-
response.headers,
11301120
)
11311121
log.debug("request_id: %s", response.headers.get("x-request-id"))
11321122

11331123
try:
11341124
response.raise_for_status()
11351125
except status_exceptions() as err: # thrown on 4xx and 5xx status code
1136-
log.debug("Encountered an HTTP status error", exc_info=True)
1126+
log.debug("Encountered an HTTP status error: %i", response.status_code)
11371127

11381128
if remaining_retries > 0 and self._should_retry(err.response):
11391129
err.response.close()
@@ -1175,7 +1165,7 @@ def _sleep_for_retry(
11751165
log.debug("%i retries left", remaining_retries)
11761166

11771167
timeout = self._calculate_retry_timeout(remaining_retries, options, response.headers if response else None)
1178-
log.info("Retrying request to %s in %f seconds", options.url, timeout)
1168+
log.info("Retrying request in %f seconds", timeout)
11791169

11801170
time.sleep(timeout)
11811171

@@ -1705,7 +1695,7 @@ async def request(
17051695
if options.follow_redirects is not None:
17061696
kwargs["follow_redirects"] = options.follow_redirects
17071697

1708-
log.debug("Sending HTTP Request: %s %s", request.method, request.url)
1698+
log.debug("Sending HTTP Request: %s", get_http_method_for_logging(request.method))
17091699

17101700
response = None
17111701
try:
@@ -1715,7 +1705,7 @@ async def request(
17151705
**kwargs,
17161706
)
17171707
except timeout_exceptions() as err:
1718-
log.debug("Encountered a timeout exception", exc_info=True)
1708+
log.debug("Encountered a timeout exception: %s", type(err).__name__)
17191709

17201710
if remaining_retries > 0:
17211711
await self._sleep_for_retry(
@@ -1732,7 +1722,7 @@ async def request(
17321722
# Propagate OpenAIErrors as-is, without retrying or wrapping in APIConnectionError
17331723
raise err
17341724
except Exception as err:
1735-
log.debug("Encountered Exception", exc_info=True)
1725+
log.debug("Encountered exception: %s", type(err).__name__)
17361726

17371727
if remaining_retries > 0:
17381728
await self._sleep_for_retry(
@@ -1747,19 +1737,16 @@ async def request(
17471737
raise APIConnectionError(request=request) from err
17481738

17491739
log.debug(
1750-
'HTTP Response: %s %s "%i %s" %s',
1751-
request.method,
1752-
request.url,
1740+
"HTTP Response: %s %i",
1741+
get_http_method_for_logging(request.method),
17531742
response.status_code,
1754-
response.reason_phrase,
1755-
response.headers,
17561743
)
17571744
log.debug("request_id: %s", response.headers.get("x-request-id"))
17581745

17591746
try:
17601747
response.raise_for_status()
17611748
except status_exceptions() as err: # thrown on 4xx and 5xx status code
1762-
log.debug("Encountered an HTTP status error", exc_info=True)
1749+
log.debug("Encountered an HTTP status error: %i", response.status_code)
17631750

17641751
if remaining_retries > 0 and self._should_retry(err.response):
17651752
await err.response.aclose()
@@ -1801,7 +1788,7 @@ async def _sleep_for_retry(
18011788
log.debug("%i retries left", remaining_retries)
18021789

18031790
timeout = self._calculate_retry_timeout(remaining_retries, options, response.headers if response else None)
1804-
log.info("Retrying request to %s in %f seconds", options.url, timeout)
1791+
log.info("Retrying request in %f seconds", timeout)
18051792

18061793
await anyio.sleep(timeout)
18071794

‎src/openai/_legacy_response.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -314,7 +314,7 @@ def _parse(self, *, to: type[_T] | None = None) -> R | _T:
314314
try:
315315
data = response.json()
316316
except Exception as exc:
317-
log.debug("Could not read JSON from response data due to %s - %s", type(exc), exc)
317+
log.debug("Could not read JSON from response data due to %s", type(exc).__name__)
318318
else:
319319
return self._client._process_response_data(
320320
data=data,

‎src/openai/_response.py‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -247,7 +247,7 @@ def _parse(self, *, to: type[_T] | None = None) -> R | _T:
247247
try:
248248
data = response.json()
249249
except Exception as exc:
250-
log.debug("Could not read JSON from response data due to %s - %s", type(exc), exc)
250+
log.debug("Could not read JSON from response data due to %s", type(exc).__name__)
251251
else:
252252
return self._client._process_response_data(
253253
data=data,

‎src/openai/_utils/_logs.py‎

Lines changed: 10 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -5,30 +5,36 @@
55
from ._utils import is_dict
66

77
logger: logging.Logger = logging.getLogger("openai")
8-
httpx2_logger: logging.Logger = logging.getLogger("httpx2")
98

109

1110
SENSITIVE_HEADERS = {"api-key", "authorization", "x-amz-security-token"}
1211

1312

1413
def _basic_config() -> None:
15-
# e.g. [2023-10-05 14:12:26 - openai._base_client:818 - DEBUG] HTTP Request: POST http://127.0.0.1:4010/foo/bar "200 OK"
14+
# e.g. [2023-10-05 14:12:26 - openai._base_client:818 - DEBUG] HTTP Response: POST 200
1615
logging.basicConfig(
1716
format="[%(asctime)s - %(name)s:%(lineno)d - %(levelname)s] %(message)s",
1817
datefmt="%Y-%m-%d %H:%M:%S",
1918
)
2019

2120

21+
def get_http_method_for_logging(method: str) -> str:
22+
normalized = method.upper()
23+
if normalized in {"GET", "HEAD", "POST", "PUT", "DELETE", "CONNECT", "OPTIONS", "TRACE", "PATCH"}:
24+
return normalized
25+
return "<custom>"
26+
27+
2228
def setup_logging() -> None:
29+
# Transport loggers may include complete URLs. Leave their configuration to
30+
# the application instead of enabling them with the SDK's logging switch.
2331
env = os.environ.get("OPENAI_LOG")
2432
if env == "debug":
2533
_basic_config()
2634
logger.setLevel(logging.DEBUG)
27-
httpx2_logger.setLevel(logging.DEBUG)
2835
elif env == "info":
2936
_basic_config()
3037
logger.setLevel(logging.INFO)
31-
httpx2_logger.setLevel(logging.INFO)
3238

3339

3440
class SensitiveHeadersFilter(logging.Filter):

‎src/openai/resources/beta/realtime/realtime.py‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -277,7 +277,7 @@ async def recv_bytes(self) -> bytes:
277277
then you can call `.parse_event(data)`.
278278
"""
279279
message = await self._connection.recv(decode=False)
280-
log.debug(f"Received websocket message: %s", message)
280+
log.debug("Received WebSocket message: %i bytes", len(message))
281281
return message
282282

283283
async def send(self, event: RealtimeClientEvent | RealtimeClientEventParam) -> None:
@@ -369,9 +369,9 @@ async def __aenter__(self) -> AsyncRealtimeConnection:
369369
**extra_query,
370370
},
371371
)
372-
log.debug("Connecting to %s", url)
372+
log.debug("Connecting to WebSocket API")
373373
if self.__websocket_connection_options:
374-
log.debug("Connection options: %s", self.__websocket_connection_options)
374+
log.debug("Custom WebSocket connection options provided")
375375

376376
self.__connection = AsyncRealtimeConnection(
377377
await connect(
@@ -460,7 +460,7 @@ def recv_bytes(self) -> bytes:
460460
then you can call `.parse_event(data)`.
461461
"""
462462
message = self._connection.recv(decode=False)
463-
log.debug(f"Received websocket message: %s", message)
463+
log.debug("Received WebSocket message: %i bytes", len(message))
464464
return message
465465

466466
def send(self, event: RealtimeClientEvent | RealtimeClientEventParam) -> None:
@@ -552,9 +552,9 @@ def __enter__(self) -> RealtimeConnection:
552552
**extra_query,
553553
},
554554
)
555-
log.debug("Connecting to %s", url)
555+
log.debug("Connecting to WebSocket API")
556556
if self.__websocket_connection_options:
557-
log.debug("Connection options: %s", self.__websocket_connection_options)
557+
log.debug("Custom WebSocket connection options provided")
558558

559559
self.__connection = RealtimeConnection(
560560
connect(

‎src/openai/resources/beta/responses/responses.py‎

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -4175,7 +4175,7 @@ async def recv_bytes(self) -> bytes:
41754175
then you can call `.parse_event(data)`.
41764176
"""
41774177
message = await self._connection.recv(decode=False)
4178-
log.debug(f"Received WebSocket message: %s", message)
4178+
log.debug("Received WebSocket message: %i bytes", len(message))
41794179
return message
41804180

41814181
async def send(self, event: BetaResponsesClientEvent | BetaResponsesClientEventParam) -> None:
@@ -4300,7 +4300,7 @@ async def _send(data: str) -> None:
43004300
try:
43014301
await self._send_queue.flush_async(_send)
43024302
except Exception:
4303-
log.warning("Failed to flush send queue after reconnect", exc_info=True)
4303+
log.warning("Failed to flush send queue after reconnect")
43044304

43054305
def on(
43064306
self, event_type: str, handler: Callable[..., Any] | None = None
@@ -4524,9 +4524,9 @@ async def _connect_ws(self, extra_query: Query, extra_headers: Headers) -> Async
45244524
**extra_query,
45254525
},
45264526
)
4527-
log.debug("Connecting to %s", url)
4527+
log.debug("Connecting to WebSocket API")
45284528
if self.__websocket_connection_options:
4529-
log.debug("Connection options: %s", self.__websocket_connection_options)
4529+
log.debug("Custom WebSocket connection options provided")
45304530

45314531
return await connect(
45324532
str(url),
@@ -4632,7 +4632,7 @@ def recv_bytes(self) -> bytes:
46324632
then you can call `.parse_event(data)`.
46334633
"""
46344634
message = self._connection.recv(decode=False)
4635-
log.debug(f"Received WebSocket message: %s", message)
4635+
log.debug("Received WebSocket message: %i bytes", len(message))
46364636
return message
46374637

46384638
def send(self, event: BetaResponsesClientEvent | BetaResponsesClientEventParam) -> None:
@@ -4751,7 +4751,7 @@ def _flush_send_queue(self) -> None:
47514751
try:
47524752
self._send_queue.flush_sync(lambda data: self._connection.send(data))
47534753
except Exception:
4754-
log.warning("Failed to flush send queue after reconnect", exc_info=True)
4754+
log.warning("Failed to flush send queue after reconnect")
47554755

47564756
def on(
47574757
self, event_type: str, handler: Callable[..., Any] | None = None
@@ -4969,9 +4969,9 @@ def _connect_ws(self, extra_query: Query, extra_headers: Headers) -> WebSocketCo
49694969
**extra_query,
49704970
},
49714971
)
4972-
log.debug("Connecting to %s", url)
4972+
log.debug("Connecting to WebSocket API")
49734973
if self.__websocket_connection_options:
4974-
log.debug("Connection options: %s", self.__websocket_connection_options)
4974+
log.debug("Custom WebSocket connection options provided")
49754975

49764976
return connect(
49774977
str(url),

‎src/openai/resources/realtime/realtime.py‎

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -340,7 +340,7 @@ async def recv_bytes(self) -> bytes:
340340
then you can call `.parse_event(data)`.
341341
"""
342342
message = await self._connection.recv(decode=False)
343-
log.debug(f"Received WebSocket message: %s", message)
343+
log.debug("Received WebSocket message: %i bytes", len(message))
344344
return message
345345

346346
async def send(self, event: RealtimeClientEvent | RealtimeClientEventParam) -> None:
@@ -464,7 +464,7 @@ async def _send(data: str) -> None:
464464
try:
465465
await self._send_queue.flush_async(_send)
466466
except Exception:
467-
log.warning("Failed to flush send queue after reconnect", exc_info=True)
467+
log.warning("Failed to flush send queue after reconnect")
468468

469469
def on(
470470
self, event_type: str, handler: Callable[..., Any] | None = None
@@ -704,9 +704,9 @@ async def _connect_ws(self, extra_query: Query, extra_headers: Headers) -> Async
704704
**extra_query,
705705
},
706706
)
707-
log.debug("Connecting to %s", url)
707+
log.debug("Connecting to WebSocket API")
708708
if self.__websocket_connection_options:
709-
log.debug("Connection options: %s", self.__websocket_connection_options)
709+
log.debug("Custom WebSocket connection options provided")
710710

711711
return await connect(
712712
str(url),
@@ -820,7 +820,7 @@ def recv_bytes(self) -> bytes:
820820
then you can call `.parse_event(data)`.
821821
"""
822822
message = self._connection.recv(decode=False)
823-
log.debug(f"Received WebSocket message: %s", message)
823+
log.debug("Received WebSocket message: %i bytes", len(message))
824824
return message
825825

826826
def send(self, event: RealtimeClientEvent | RealtimeClientEventParam) -> None:
@@ -938,7 +938,7 @@ def _flush_send_queue(self) -> None:
938938
try:
939939
self._send_queue.flush_sync(lambda data: self._connection.send(data))
940940
except Exception:
941-
log.warning("Failed to flush send queue after reconnect", exc_info=True)
941+
log.warning("Failed to flush send queue after reconnect")
942942

943943
def on(
944944
self, event_type: str, handler: Callable[..., Any] | None = None
@@ -1172,9 +1172,9 @@ def _connect_ws(self, extra_query: Query, extra_headers: Headers) -> WebSocketCo
11721172
**extra_query,
11731173
},
11741174
)
1175-
log.debug("Connecting to %s", url)
1175+
log.debug("Connecting to WebSocket API")
11761176
if self.__websocket_connection_options:
1177-
log.debug("Connection options: %s", self.__websocket_connection_options)
1177+
log.debug("Custom WebSocket connection options provided")
11781178

11791179
return connect(
11801180
str(url),

0 commit comments

Comments
 (0)