Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix(logs): redact sensitive headers #1850

Merged
merged 10 commits into from
Nov 6, 2024
Merged
Show file tree
Hide file tree
Changes from 5 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 2 additions & 1 deletion src/openai/_base_client.py
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,7 @@
HttpxRequestFiles,
ModelBuilderProtocol,
)
from ._utils import is_dict, is_list, asyncify, is_given, lru_cache, is_mapping
from ._utils import APIKeyFilter, is_dict, is_list, asyncify, is_given, lru_cache, is_mapping
from ._compat import model_copy, model_dump
from ._models import GenericModel, FinalRequestOptions, validate_type, construct_type
from ._response import (
Expand Down Expand Up @@ -90,6 +90,7 @@
from ._legacy_response import LegacyAPIResponse

log: logging.Logger = logging.getLogger(__name__)
log.addFilter(APIKeyFilter())

# TODO: make base page type vars covariant
SyncPageT = TypeVar("SyncPageT", bound="BaseSyncPage[Any]")
Expand Down
1 change: 1 addition & 0 deletions src/openai/_utils/__init__.py
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
from ._logs import APIKeyFilter as APIKeyFilter
from ._sync import asyncify as asyncify
from ._proxy import LazyProxy as LazyProxy
from ._utils import (
Expand Down
14 changes: 14 additions & 0 deletions src/openai/_utils/_logs.py
Original file line number Diff line number Diff line change
@@ -1,5 +1,7 @@
import os
import logging
from typing import Any, Dict
from typing_extensions import override

logger: logging.Logger = logging.getLogger("openai")
httpx_logger: logging.Logger = logging.getLogger("httpx")
Expand All @@ -23,3 +25,15 @@ def setup_logging() -> None:
_basic_config()
logger.setLevel(logging.INFO)
httpx_logger.setLevel(logging.INFO)


class APIKeyFilter(logging.Filter):
kristapratico marked this conversation as resolved.
Show resolved Hide resolved
@override
def filter(self, record: logging.LogRecord) -> bool:
if isinstance(record.args, dict) and "headers" in record.args:
if isinstance(record.args["headers"], dict):
logged_headers: Dict[str, Any] = record.args["headers"]
for header in logged_headers:
if header.lower() in ["api-key", "authorization"]:
logged_headers[header] = "<redacted>"
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: we have an is_dict() header that would make this slightly cleaner imo

Suggested change
if isinstance(record.args, dict) and "headers" in record.args:
if isinstance(record.args["headers"], dict):
logged_headers: Dict[str, Any] = record.args["headers"]
for header in logged_headers:
if header.lower() in ["api-key", "authorization"]:
logged_headers[header] = "<redacted>"
if is_dict(record.args) and "headers" in record.args and is_dict(record.args["headers"]):
headers = record.args["headers"]
for header in headers:
if str(header).lower() in ["api-key", "authorization"]:
headers[header] = "<redacted>"

and from ._utils import is_dict.

also a minor micro optimisation but I think we should extract the list of headers, e.g.

SENSITIVE_HEADERS = {"api-key", "authorization"}

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

also I haven't actually written a log filter before, is it bad that this mutates the original headers arg? i.e. should it be this?

            headers = record.args["headers"] = {**record.args["headers"]}

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Updated with your revisions, thanks! The logging docs for filter permits in-place modification:

If deemed appropriate, the record may be modified in-place.

return True
92 changes: 92 additions & 0 deletions tests/test_utils/test_logging.py
kristapratico marked this conversation as resolved.
Show resolved Hide resolved
Original file line number Diff line number Diff line change
@@ -0,0 +1,92 @@
import logging
from typing import Any, Dict, cast

import pytest

from openai._utils import APIKeyFilter


@pytest.fixture
def logger_with_filter() -> logging.Logger:
logger = logging.getLogger("test_logger")
logger.setLevel(logging.DEBUG)
logger.addFilter(APIKeyFilter())
return logger


def test_keys_redacted(logger_with_filter: logging.Logger, caplog: pytest.LogCaptureFixture) -> None:
with caplog.at_level(logging.DEBUG):
logger_with_filter.debug(
"Request options: %s",
{
"method": "post",
"url": "chat/completions",
"headers": {"api-key": "12345", "Authorization": "Bearer token"}
},
)

log_record = cast(Dict[str, Any], caplog.records[0].args)
assert log_record["method"] == "post"
assert log_record["url"] == "chat/completions"
assert log_record["headers"]["api-key"] == "<redacted>"
assert log_record["headers"]["Authorization"] == "<redacted>"
kristapratico marked this conversation as resolved.
Show resolved Hide resolved


def test_keys_redacted_case_insensitive(logger_with_filter: logging.Logger, caplog: pytest.LogCaptureFixture) -> None:
with caplog.at_level(logging.DEBUG):
logger_with_filter.debug(
"Request options: %s",
{
"method": "post",
"url": "chat/completions",
"headers": {"Api-key": "12345", "authorization": "Bearer token"}
},
)

log_record = cast(Dict[str, Any], caplog.records[0].args)
assert log_record["method"] == "post"
assert log_record["url"] == "chat/completions"
assert log_record["headers"]["Api-key"] == "<redacted>"
assert log_record["headers"]["authorization"] == "<redacted>"


def test_no_headers(logger_with_filter: logging.Logger, caplog: pytest.LogCaptureFixture) -> None:
with caplog.at_level(logging.DEBUG):
logger_with_filter.debug(
"Request options: %s",
{
"method": "post",
"url": "chat/completions"
},
)

log_record = cast(Dict[str, Any], caplog.records[0].args)
assert log_record["method"] == "post"
assert log_record["url"] == "chat/completions"
assert "api-key" not in log_record
assert "Authorization" not in log_record


def test_headers_without_sensitive_info(logger_with_filter: logging.Logger, caplog: pytest.LogCaptureFixture) -> None:
with caplog.at_level(logging.DEBUG):
logger_with_filter.debug(
"Request options: %s",
{
"method": "post",
"url": "chat/completions",
"headers": {"custom": "value"}
}
)

log_record = cast(Dict[str, Any], caplog.records[0].args)
assert log_record["method"] == "post"
assert log_record["url"] == "chat/completions"
assert log_record["headers"] == {"custom": "value"}


def test_standard_debug_msg(logger_with_filter: logging.Logger, caplog: pytest.LogCaptureFixture) -> None:
with caplog.at_level(logging.DEBUG):
logger_with_filter.debug(
"Sending HTTP Request: %s %s", "POST", "chat/completions"
)
assert caplog.messages[0] == "Sending HTTP Request: POST chat/completions"