diff --git a/py/src/braintrust/__init__.py b/py/src/braintrust/__init__.py index 1e66fced..2513a0e7 100644 --- a/py/src/braintrust/__init__.py +++ b/py/src/braintrust/__init__.py @@ -81,6 +81,7 @@ def is_equal(expected, output): _internal_reset_global_state, # noqa: F401 # type: ignore[reportUnusedImport] _internal_with_custom_background_logger, # noqa: F401 # type: ignore[reportUnusedImport] ) +from .logs import BraintrustLogHandler as BraintrustLogHandler from .sandbox import RegisteredSandboxFunction as RegisteredSandboxFunction from .sandbox import RegisterSandboxResult as RegisterSandboxResult from .sandbox import SandboxConfig as SandboxConfig diff --git a/py/src/braintrust/api/_transport.py b/py/src/braintrust/api/_transport.py index f178dfb8..509dabd3 100644 --- a/py/src/braintrust/api/_transport.py +++ b/py/src/braintrust/api/_transport.py @@ -1,5 +1,7 @@ """Legacy and policy-aware HTTP transport primitives for the Braintrust SDK.""" +import contextlib +import contextvars import dataclasses import datetime import http.cookiejar @@ -29,6 +31,21 @@ logger = logging.getLogger(__name__) +_INTERNAL_HTTP_TRANSPORT = contextvars.ContextVar("braintrust_internal_http_transport", default=False) + + +@contextlib.contextmanager +def _internal_http_transport(): + token = _INTERNAL_HTTP_TRANSPORT.set(True) + try: + yield + finally: + _INTERNAL_HTTP_TRANSPORT.reset(token) + + +def _is_internal_http_transport() -> bool: + return _INTERNAL_HTTP_TRANSPORT.get() + class _RejectCookiesPolicy(http.cookiejar.DefaultCookiePolicy): def set_ok(self, cookie: Any, request: Any) -> bool: @@ -159,19 +176,24 @@ def _set_session_token(self) -> None: self.session.headers.update({"Authorization": f"Bearer {self.token}"}) def get(self, path: str, *args: Any, **kwargs: Any) -> requests.Response: - return self.session.get(_urljoin(self.base_url, path), *args, **kwargs) + with _internal_http_transport(): + return self.session.get(_urljoin(self.base_url, path), *args, **kwargs) def post(self, path: str, *args: Any, **kwargs: Any) -> requests.Response: - return self.session.post(_urljoin(self.base_url, path), *args, **kwargs) + with _internal_http_transport(): + return self.session.post(_urljoin(self.base_url, path), *args, **kwargs) def patch(self, path: str, *args: Any, **kwargs: Any) -> requests.Response: - return self.session.patch(_urljoin(self.base_url, path), *args, **kwargs) + with _internal_http_transport(): + return self.session.patch(_urljoin(self.base_url, path), *args, **kwargs) def put(self, path: str, *args: Any, **kwargs: Any) -> requests.Response: - return self.session.put(_urljoin(self.base_url, path), *args, **kwargs) + with _internal_http_transport(): + return self.session.put(_urljoin(self.base_url, path), *args, **kwargs) def delete(self, path: str, *args: Any, **kwargs: Any) -> requests.Response: - return self.session.delete(_urljoin(self.base_url, path), *args, **kwargs) + with _internal_http_transport(): + return self.session.delete(_urljoin(self.base_url, path), *args, **kwargs) def get_json(self, object_type: str, args: Mapping[str, Any] | None = None) -> Mapping[str, Any]: resp = self.get(f"/{object_type}", params=args) @@ -305,17 +327,18 @@ def request( attempt_timeout = min(policy.timeout, remaining) if remaining is not None else policy.timeout try: - response = self.session.request( - method, - url, - params=params, - json=json, - data=data, - headers=headers, - timeout=attempt_timeout, - stream=stream, - **kwargs, - ) + with _internal_http_transport(): + response = self.session.request( + method, + url, + params=params, + json=json, + data=data, + headers=headers, + timeout=attempt_timeout, + stream=stream, + **kwargs, + ) except requests.exceptions.RequestException as exc: if not is_retryable_request_exception(exc): error = BraintrustTransportError(method=method, url=url, attempts=attempt, retryable=False) diff --git a/py/src/braintrust/logger.py b/py/src/braintrust/logger.py index f3c854eb..8dfe4fe6 100644 --- a/py/src/braintrust/logger.py +++ b/py/src/braintrust/logger.py @@ -8,6 +8,7 @@ import dataclasses import datetime import hashlib +import importlib import inspect import io import json @@ -21,6 +22,7 @@ import types import uuid from abc import ABC, abstractmethod +from collections import Counter from collections.abc import Callable, Iterator, Mapping, MutableMapping, Sequence from functools import partial, wraps from multiprocessing import cpu_count @@ -131,6 +133,66 @@ # 6 MB for the AWS lambda gateway (from our own testing). DEFAULT_MAX_REQUEST_SIZE = 6 * 1024 * 1024 +LogLevel = Literal["trace", "debug", "info", "warn", "error", "fatal"] +_LOG_LEVELS: tuple[LogLevel, ...] = ("trace", "debug", "info", "warn", "error", "fatal") + +_TEMPLATELIB = importlib.import_module("string.templatelib") if sys.version_info >= (3, 14) else None + + +class _LogTemplateParameters(dict[str, object]): + """Preserve placeholders whose values were not provided.""" + + def __missing__(self, key: str) -> str: + return "{" + key + "}" + + +def _is_t_string(value: Any) -> bool: + return _TEMPLATELIB is not None and isinstance(value, _TEMPLATELIB.Template) + + +def _render_t_string(template: Any) -> tuple[str, str, dict[str, object]]: + """Render a Python 3.14 t-string and retain its template structure.""" + assert _TEMPLATELIB is not None + + rendered_parts: list[str] = [] + template_parts: list[str] = [] + parameters: dict[str, object] = {} + parameter_names = [ + interpolation.expression.strip() or str(index) for index, interpolation in enumerate(template.interpolations) + ] + parameter_name_counts = Counter(parameter_names) + parameter_name_occurrences: Counter[str] = Counter() + + for parameter_name, literal, interpolation in zip(parameter_names, template.strings, template.interpolations): + rendered_parts.append(literal) + template_parts.append(literal.replace("{", "{{").replace("}", "}}")) + + placeholder = "{" + interpolation.expression + if interpolation.conversion is not None: + placeholder += "!" + interpolation.conversion + if interpolation.format_spec: + placeholder += ":" + interpolation.format_spec + placeholder += "}" + template_parts.append(placeholder) + + if parameter_name_counts[parameter_name] > 1: + occurrence = parameter_name_occurrences[parameter_name] + parameter_name_occurrences[parameter_name] += 1 + parameter_name = f"{parameter_name}.{occurrence}" + parameters[parameter_name] = interpolation.value + try: + converted = _TEMPLATELIB.convert(interpolation.value, interpolation.conversion) + rendered_parts.append(format(converted, interpolation.format_spec)) + except Exception: + # Logging should not disrupt the application because an interpolation + # uses an unsupported conversion or format specifier. + rendered_parts.append(placeholder) + + final_literal = template.strings[-1] + rendered_parts.append(final_literal) + template_parts.append(final_literal.replace("{", "{{").replace("}", "}}")) + return "".join(rendered_parts), "".join(template_parts), parameters + @dataclasses.dataclass class Logs3OverflowInputRow: @@ -4820,7 +4882,7 @@ def __init__( internal_data: dict[str, Any] = dict( metrics=dict( - start=start_time or time.time(), + start=start_time if start_time is not None else time.time(), ), # Set type first, in case they override it in `span_attributes`. span_attributes=dict(**{"type": type, "name": name, **span_attributes}, exec_counter=exec_counter), @@ -5896,6 +5958,7 @@ def __init__( # fallbacks when generating links self._link_args = link_args self.state = state or _state + self._baseline_trace_id = self.state.id_generator.get_trace_id() @property def org_id(self) -> str: @@ -5974,6 +6037,123 @@ def log( return span.id + def emit_log( + self, + body: Any, + level: LogLevel, + metadata: dict[str, Any] | None = None, + **parameters: object, + ) -> str: + """Capture a log record, associating it with the active span when one exists. + + The log is stored as an independent row. If a Braintrust or OpenTelemetry + span is active, the row reuses its span and trace IDs for correlation. + Otherwise, the row uses this logger's baseline trace ID. + + String bodies may contain ``str.format``-style placeholders. Keyword + parameters are interpolated into the body and retained in metadata along + with the original template. Missing parameters remain as placeholders. + On Python 3.14 and newer, ``string.templatelib.Template`` bodies are + rendered using their embedded interpolation values, which are also + retained in metadata. + + :param body: The log body. May be a Python 3.14+ t-string or any + JSON-serializable value when no template parameters are provided. + :param level: The OpenTelemetry log severity: ``trace``, ``debug``, + ``info``, ``warn``, ``error``, or ``fatal``. + :param metadata: Optional JSON-serializable attributes for the log. + :param parameters: Values for named placeholders in a string body. + :returns: The unique ID of the captured log row. + """ + rendered_body = body + rendered_metadata = metadata + if _is_t_string(body): + if parameters: + raise TypeError("T-string bodies already contain their interpolation values") + rendered_body, template, t_string_parameters = _render_t_string(body) + rendered_metadata = dict(metadata) if metadata is not None else {} + rendered_metadata.update( + {f"braintrust.template.parameter.{key}": value for key, value in t_string_parameters.items()} + ) + rendered_metadata["braintrust.template"] = template + elif parameters: + if not isinstance(body, str): + raise TypeError("Log body must be a string when template parameters are provided") + rendered_metadata = dict(metadata) if metadata is not None else {} + rendered_metadata.update( + {f"braintrust.template.parameter.{key}": value for key, value in parameters.items()} + ) + rendered_metadata["braintrust.template"] = body + try: + rendered_body = body.format_map(_LogTemplateParameters(parameters)) + except Exception: + # Logging should not disrupt the application because a template + # contains malformed braces or an unsupported format specifier. + rendered_body = body + + return self._emit_log_record( + body=rendered_body, + level=level, + metadata=rendered_metadata, + captured_at=time.time(), + ) + + def _emit_log_record( + self, + body: Any, + level: LogLevel, + metadata: dict[str, Any] | None, + captured_at: float, + ) -> str: + if level not in _LOG_LEVELS: + valid_levels = ", ".join(_LOG_LEVELS) + raise ValueError(f"Invalid log level {level!r}. Expected one of: {valid_levels}") + + span_info = self.state.context_manager.get_current_span_info() + span = self._start_span_impl( + name="Log", + type=SpanTypeAttribute.LOG, + span_attributes={"name": None, "log_level": level}, + start_time=captured_at, + set_current=False, + span_id=span_info.span_id if span_info else None, + root_span_id=span_info.trace_id if span_info else self._baseline_trace_id, + lookup_span_parent=False, + output=body, + metadata=metadata, + metrics={"end": captured_at}, + created=datetime.datetime.fromtimestamp(captured_at, datetime.timezone.utc).isoformat(), + ) + + if not self.async_flush: + self.flush() + + return span.id + + def trace(self, body: Any, metadata: dict[str, Any] | None = None, **parameters: object) -> str: + """Capture a trace-level log.""" + return self.emit_log(body=body, level="trace", metadata=metadata, **parameters) + + def debug(self, body: Any, metadata: dict[str, Any] | None = None, **parameters: object) -> str: + """Capture a debug-level log.""" + return self.emit_log(body=body, level="debug", metadata=metadata, **parameters) + + def info(self, body: Any, metadata: dict[str, Any] | None = None, **parameters: object) -> str: + """Capture an info-level log.""" + return self.emit_log(body=body, level="info", metadata=metadata, **parameters) + + def warn(self, body: Any, metadata: dict[str, Any] | None = None, **parameters: object) -> str: + """Capture a warn-level log.""" + return self.emit_log(body=body, level="warn", metadata=metadata, **parameters) + + def error(self, body: Any, metadata: dict[str, Any] | None = None, **parameters: object) -> str: + """Capture an error-level log.""" + return self.emit_log(body=body, level="error", metadata=metadata, **parameters) + + def fatal(self, body: Any, metadata: dict[str, Any] | None = None, **parameters: object) -> str: + """Capture a fatal-level log.""" + return self.emit_log(body=body, level="fatal", metadata=metadata, **parameters) + def log_feedback( self, id: str, diff --git a/py/src/braintrust/logs.py b/py/src/braintrust/logs.py new file mode 100644 index 00000000..9c178409 --- /dev/null +++ b/py/src/braintrust/logs.py @@ -0,0 +1,112 @@ +"""Adapters for forwarding standard-library log records to Braintrust.""" + +import logging +from collections.abc import Mapping +from typing import Any + +from .api._transport import _is_internal_http_transport +from .logger import Logger, LogLevel + + +_STANDARD_LOG_RECORD_ATTRIBUTES = frozenset(vars(logging.LogRecord("", logging.NOTSET, "", 0, "", (), None))) | { + "asctime", + "message", +} +_IGNORED_LOGGER_PREFIXES = ("braintrust",) + + +def _log_level(level: int) -> LogLevel: + if level >= logging.CRITICAL: + return "fatal" + if level >= logging.ERROR: + return "error" + if level >= logging.WARNING: + return "warn" + if level >= logging.INFO: + return "info" + if level >= logging.DEBUG: + return "debug" + return "trace" + + +def _is_ignored_logger(name: str) -> bool: + return any(name == prefix or name.startswith(f"{prefix}.") for prefix in _IGNORED_LOGGER_PREFIXES) + + +def _uses_named_percent_parameters(template: str) -> bool: + search_from = 0 + while (placeholder_index := template.find("%(", search_from)) >= 0: + percent_run_start = placeholder_index + while percent_run_start > 0 and template[percent_run_start - 1] == "%": + percent_run_start -= 1 + if (placeholder_index - percent_run_start) % 2 == 0: + return True + search_from = placeholder_index + 2 + return False + + +class _InternalLogFilter(logging.Filter): + def filter(self, record: logging.LogRecord) -> bool: + return not _is_ignored_logger(record.name) and not _is_internal_http_transport() + + +def _record_metadata(record: logging.LogRecord) -> dict[str, Any]: + metadata = { + key: value + for key, value in vars(record).items() + if key not in _STANDARD_LOG_RECORD_ATTRIBUTES and not key.startswith("_") + } + + if record.args and isinstance(record.msg, str): + metadata["braintrust.template"] = record.msg + if isinstance(record.args, Mapping) and _uses_named_percent_parameters(record.msg): + parameters = record.args.items() + else: + positional_args = (record.args,) if isinstance(record.args, Mapping) else record.args + parameters = enumerate(positional_args) + metadata.update({f"braintrust.template.parameter.{key}": value for key, value in parameters}) + + metadata.update( + { + "logger.name": record.name, + "code.file.path": record.pathname, + "code.function.name": record.funcName, + "code.line.number": record.lineno, + } + ) + + return metadata + + +class BraintrustLogHandler(logging.Handler): + """Forward Python ``logging`` records to a Braintrust logger. + + Attach this handler explicitly with ``logging.Logger.addHandler``. Records + emitted by Braintrust or while its HTTP transport is active are ignored to + prevent logging recursion. + """ + + def __init__(self, logger: Logger, level: int | str = logging.NOTSET): + super().__init__(level=level) + self._logger = logger + # Handler.handle() runs filters before acquiring its lock. Filtering + # internal transport logs here prevents a shutdown flush from waiting + # on a worker thread blocked on that same lock. + self.addFilter(_InternalLogFilter()) + + def emit(self, record: logging.LogRecord) -> None: + try: + self._logger._emit_log_record( + body=self.format(record), + level=_log_level(record.levelno), + metadata=_record_metadata(record), + captured_at=record.created, + ) + except Exception: + self.handleError(record) + + def flush(self) -> None: + self._logger.flush() + + +__all__ = ["BraintrustLogHandler"] diff --git a/py/src/braintrust/otel/test_otel_bt_integration.py b/py/src/braintrust/otel/test_otel_bt_integration.py index 579082d9..b6d9ebff 100644 --- a/py/src/braintrust/otel/test_otel_bt_integration.py +++ b/py/src/braintrust/otel/test_otel_bt_integration.py @@ -122,6 +122,22 @@ def test_mixed_otel_bt_tracing_with_bt_logger_first(otel_fixture): assert s2_span_id in s3["span_parents"] +def test_emit_log_uses_active_otel_span(otel_fixture): + logger = init_test_logger(__name__) + tracer = otel_fixture.tracer + memory_logger = otel_fixture.memory_logger + + with tracer.start_as_current_span("owner") as owner: + log_id = logger.emit_log(body="Inside OTel span", level="info") + owner_context = owner.get_span_context() + + [log_row] = memory_logger.pop() + assert log_row["id"] == log_id + assert log_row["span_id"] == format(owner_context.span_id, "016x") + assert log_row["root_span_id"] == format(owner_context.trace_id, "032x") + assert not log_row.get("span_parents") + + def test_mixed_otel_bt_tracing_with_experiment_parent(otel_fixture): experiment = init_test_exp("otel-bt-mixed", "test-mixed-tracing-experiment") tracer = otel_fixture.tracer diff --git a/py/src/braintrust/span_types.py b/py/src/braintrust/span_types.py index b82a6f89..59ef74d6 100644 --- a/py/src/braintrust/span_types.py +++ b/py/src/braintrust/span_types.py @@ -19,6 +19,7 @@ class SpanTypeAttribute(str, Enum): CLASSIFIER = "classifier" REVIEW = "review" QUESTION = "question" + LOG = "log" class SpanPurpose(str, Enum): diff --git a/py/src/braintrust/test_logger.py b/py/src/braintrust/test_logger.py index 7356a273..c642d8a6 100644 --- a/py/src/braintrust/test_logger.py +++ b/py/src/braintrust/test_logger.py @@ -2,10 +2,12 @@ # pyright: reportPrivateUsage=false import asyncio import builtins +import importlib import inspect import json import logging import os +import sys import threading import time from collections.abc import AsyncGenerator @@ -1364,6 +1366,224 @@ def test_logger_log_accepts_model_dump_metadata(with_memory_logger): assert logs[0]["metadata"] == {"foo": "bar"} +def test_logger_emit_log_without_active_span(with_memory_logger): + test_logger = init_test_logger(__name__) + + first_id = test_logger.emit_log( + body="Payment failed", + level="error", + metadata={"payment_id": "pay_123"}, + ) + second_id = test_logger.emit_log(body="Retrying payment", level="info") + + logs = with_memory_logger.pop() + assert len(logs) == 2 + first, second = logs + assert first_id == first["id"] + assert second_id == second["id"] + assert first["id"] != second["id"] + assert first["span_id"] != second["span_id"] + assert first["root_span_id"] == second["root_span_id"] + assert not first.get("span_parents") + assert first["output"] == "Payment failed" + assert "error" not in first + assert first["metadata"] == {"payment_id": "pay_123"} + assert "name" not in first["span_attributes"] + assert first["span_attributes"]["type"] == "log" + assert first["span_attributes"]["log_level"] == "error" + assert first["metrics"]["start"] == first["metrics"]["end"] + assert "otel" not in first.get("context", {}) + assert "error" not in second + assert not second.get("metadata") + assert second["span_attributes"]["log_level"] == "info" + + +def test_logger_emit_log_enqueues_single_row(with_memory_logger): + test_logger = init_test_logger(__name__) + + test_logger.info("Payment completed", metadata={"payment_id": "pay_123"}) + + assert len(with_memory_logger.logs) == 1 + [row] = with_memory_logger.pop() + assert row["metrics"]["start"] == row["metrics"]["end"] + assert row["_is_merge"] is False + + +def test_logger_emit_log_uses_distinct_baseline_trace_per_logger(with_memory_logger): + first_logger = init_test_logger(f"{__name__}-first") + second_logger = init_test_logger(f"{__name__}-second") + + first_logger.info("first") + second_logger.info("second") + + first, second = with_memory_logger.pop() + assert first["root_span_id"] != second["root_span_id"] + + +def test_logger_emit_log_uses_active_span(with_memory_logger): + test_logger = init_test_logger(__name__) + + with test_logger.start_span(name="owner") as owner: + log_id = test_logger.emit_log(body="Inside span", level="debug", metadata={"attempt": 1}) + + rows = with_memory_logger.pop() + log_row = next(row for row in rows if row["id"] == log_id) + owner_row = next(row for row in rows if row["span_attributes"]["name"] == "owner") + assert log_row["id"] != owner_row["id"] + assert log_row["span_id"] == owner_row["span_id"] + assert log_row["root_span_id"] == owner_row["root_span_id"] + assert not log_row.get("span_parents") + assert log_row["metadata"] == {"attempt": 1} + assert log_row["span_attributes"]["log_level"] == "debug" + assert "otel" not in log_row.get("context", {}) + + +@pytest.mark.parametrize("level", ["trace", "debug", "info", "warn", "error", "fatal"]) +def test_logger_emit_log_adds_log_level_span_attribute(with_memory_logger, level): + test_logger = init_test_logger(__name__) + + test_logger.emit_log(body="message", level=level) + + [row] = with_memory_logger.pop() + assert not row.get("metadata") + assert row["span_attributes"]["log_level"] == level + + +@pytest.mark.parametrize("method_name", ["trace", "debug", "info", "warn", "error", "fatal"]) +def test_logger_log_level_helpers(with_memory_logger, method_name): + test_logger = init_test_logger(__name__) + + log_id = getattr(test_logger, method_name)("message", metadata={"source": method_name}) + + [row] = with_memory_logger.pop() + assert row["id"] == log_id + assert row["output"] == "message" + assert row["metadata"] == {"source": method_name} + assert row["span_attributes"]["log_level"] == method_name + + +def test_logger_log_helpers_render_template_parameters(with_memory_logger): + test_logger = init_test_logger(__name__) + + log_id = test_logger.info( + "User {user_id} paid {amount:.2f} with {method}", + metadata={"source": "checkout"}, + user_id="user-123", + amount=12.5, + ) + + [row] = with_memory_logger.pop() + assert row["id"] == log_id + assert row["output"] == "User user-123 paid 12.50 with {method}" + assert row["metadata"] == { + "source": "checkout", + "braintrust.template.parameter.user_id": "user-123", + "braintrust.template.parameter.amount": 12.5, + "braintrust.template": "User {user_id} paid {amount:.2f} with {method}", + } + assert row["span_attributes"]["log_level"] == "info" + + +@pytest.mark.skipif(sys.version_info < (3, 14), reason="t-strings require Python 3.14+") +def test_logger_log_helpers_render_t_string(with_memory_logger): + templatelib = importlib.import_module("string.templatelib") + template = templatelib.Template( + "User ", + templatelib.Interpolation("user-123", "user_id"), + " paid ", + templatelib.Interpolation(12.5, "amount", "r", ">8"), + " with {card}", + ) + test_logger = init_test_logger(__name__) + + log_id = test_logger.info(template, metadata={"source": "checkout"}) + + [row] = with_memory_logger.pop() + assert row["id"] == log_id + assert row["output"] == "User user-123 paid 12.5 with {card}" + assert row["metadata"] == { + "source": "checkout", + "braintrust.template.parameter.user_id": "user-123", + "braintrust.template.parameter.amount": 12.5, + "braintrust.template": "User {user_id} paid {amount!r:>8} with {{card}}", + } + assert row["span_attributes"]["log_level"] == "info" + + +@pytest.mark.skipif(sys.version_info < (3, 14), reason="t-strings require Python 3.14+") +def test_logger_t_string_retains_repeated_expression_values(with_memory_logger): + templatelib = importlib.import_module("string.templatelib") + template = templatelib.Template( + templatelib.Interpolation(1, "next(it)"), + " ", + templatelib.Interpolation(2, "next(it)"), + ) + test_logger = init_test_logger(__name__) + + test_logger.info(template) + + [row] = with_memory_logger.pop() + assert row["output"] == "1 2" + assert row["metadata"] == { + "braintrust.template": "{next(it)} {next(it)}", + "braintrust.template.parameter.next(it).0": 1, + "braintrust.template.parameter.next(it).1": 2, + } + + +@pytest.mark.skipif(sys.version_info < (3, 14), reason="t-strings require Python 3.14+") +def test_logger_t_string_rejects_keyword_template_parameters(with_memory_logger): + templatelib = importlib.import_module("string.templatelib") + template = templatelib.Template("User ", templatelib.Interpolation("user-123", "user_id")) + test_logger = init_test_logger(__name__) + + with pytest.raises(TypeError, match="already contain their interpolation values"): + test_logger.info(template, user_id="other-user") + + assert with_memory_logger.pop() == [] + + +def test_logger_error_renders_template_without_error_field(with_memory_logger): + test_logger = init_test_logger(__name__) + + test_logger.error("Payment {payment_id} failed", payment_id="pay-123") + + [row] = with_memory_logger.pop() + assert row["output"] == "Payment pay-123 failed" + assert "error" not in row + + +def test_logger_log_helpers_do_not_format_without_parameters(with_memory_logger): + test_logger = init_test_logger(__name__) + + test_logger.info('{"key": "{value}"}') + + [row] = with_memory_logger.pop() + assert row["output"] == '{"key": "{value}"}' + assert not row.get("metadata") + assert row["span_attributes"]["log_level"] == "info" + + +def test_logger_log_template_parameters_are_safely_serialized(with_memory_logger): + test_logger = init_test_logger(__name__) + + test_logger.warn("Request failed: {error}", error=ValueError("bad request")) + + [row] = with_memory_logger.pop() + assert row["output"] == "Request failed: bad request" + assert row["metadata"]["braintrust.template.parameter.error"] == "bad request" + assert row["span_attributes"]["log_level"] == "warn" + + +def test_logger_emit_log_rejects_invalid_level(with_memory_logger): + test_logger = init_test_logger(__name__) + + with pytest.raises(ValueError, match="Invalid log level"): + test_logger.emit_log(body="message", level="warning") + + assert with_memory_logger.pop() == [] + + def test_experiment_log_accepts_model_dump_metadata(with_memory_logger): experiment = init_test_exp("test-experiment", "test-project") diff --git a/py/src/braintrust/test_logs.py b/py/src/braintrust/test_logs.py new file mode 100644 index 00000000..92527da4 --- /dev/null +++ b/py/src/braintrust/test_logs.py @@ -0,0 +1,163 @@ +import concurrent.futures +import logging +import sys +from unittest.mock import MagicMock + +import pytest +from braintrust.api._transport import HTTPConnection +from braintrust.logs import BraintrustLogHandler +from braintrust.test_helpers import init_test_logger, with_memory_logger # noqa: F401 + + +def test_handler_forwards_log_record(with_memory_logger): + handler = BraintrustLogHandler(init_test_logger(__name__)) + record = logging.LogRecord( + name="payments.checkout", + level=logging.WARNING, + pathname="/app/checkout.py", + lineno=42, + msg="Payment %s failed", + args=("pay_123",), + exc_info=None, + func="charge", + ) + record.created = 1234.5 + record.customer_id = "cus_123" + + handler.handle(record) + + assert len(with_memory_logger.logs) == 1 + [row] = with_memory_logger.pop() + assert row["output"] == "Payment pay_123 failed" + assert row["created"] == "1970-01-01T00:20:34.500000+00:00" + assert row["metrics"] == {"start": 1234.5, "end": 1234.5} + assert "otel" not in row.get("context", {}) + assert row["metadata"] == { + "braintrust.template": "Payment %s failed", + "braintrust.template.parameter.0": "pay_123", + "code.file.path": "/app/checkout.py", + "code.function.name": "charge", + "code.line.number": 42, + "customer_id": "cus_123", + "logger.name": "payments.checkout", + } + assert row["span_attributes"]["log_level"] == "warn" + + +@pytest.mark.parametrize( + ("template", "expected_output", "expected_parameters"), + [ + ("payload=%s", "payload={'id': 1}", {"braintrust.template.parameter.0": {"id": 1}}), + ("payload=%(id)s", "payload=1", {"braintrust.template.parameter.id": 1}), + ( + "literal=%%(id)s payload=%s", + "literal=%(id)s payload={'id': 1}", + {"braintrust.template.parameter.0": {"id": 1}}, + ), + ], +) +def test_handler_distinguishes_positional_and_named_mapping_arguments( + with_memory_logger, template, expected_output, expected_parameters +): + handler = BraintrustLogHandler(init_test_logger(__name__)) + record = logging.LogRecord("app", logging.INFO, __file__, 1, template, ({"id": 1},), None) + + handler.handle(record) + + [row] = with_memory_logger.pop() + assert row["output"] == expected_output + assert row["metadata"] == { + "braintrust.template": template, + **expected_parameters, + "code.file.path": __file__, + "code.function.name": None, + "code.line.number": 1, + "logger.name": "app", + } + + +def test_handler_preserves_unix_epoch_timestamp(with_memory_logger): + handler = BraintrustLogHandler(init_test_logger(__name__)) + record = logging.LogRecord("app", logging.INFO, __file__, 1, "message", (), None) + record.created = 0 + + handler.handle(record) + + [row] = with_memory_logger.pop() + assert row["created"] == "1970-01-01T00:00:00+00:00" + assert row["metrics"] == {"start": 0, "end": 0} + + +@pytest.mark.parametrize( + ("python_level", "braintrust_level"), + [ + (1, "trace"), + (logging.DEBUG, "debug"), + (logging.INFO, "info"), + (logging.WARNING, "warn"), + (logging.ERROR, "error"), + (logging.CRITICAL, "fatal"), + ], +) +def test_handler_maps_python_log_levels(with_memory_logger, python_level, braintrust_level): + handler = BraintrustLogHandler(init_test_logger(__name__)) + record = logging.LogRecord("app", python_level, __file__, 1, "message", (), None) + + handler.handle(record) + + [row] = with_memory_logger.pop() + assert row["span_attributes"]["log_level"] == braintrust_level + assert "braintrust.log_level" not in row.get("metadata", {}) + + +def test_handler_forwards_exception_info(with_memory_logger): + handler = BraintrustLogHandler(init_test_logger(__name__)) + + try: + raise ValueError("invalid payment") + except ValueError: + record = logging.LogRecord("payments", logging.ERROR, __file__, 1, "Charge failed", (), None) + record.exc_info = sys.exc_info() + + handler.handle(record) + + [row] = with_memory_logger.pop() + assert row["output"].startswith("Charge failed\nTraceback (most recent call last):") + assert row["output"].endswith("ValueError: invalid payment") + assert "error" not in row + + +def test_handler_ignores_braintrust_loggers(with_memory_logger): + handler = BraintrustLogHandler(init_test_logger(__name__)) + record = logging.LogRecord("braintrust.logger", logging.ERROR, __file__, 1, "internal", (), None) + + handler.handle(record) + + assert with_memory_logger.pop() == [] + + +def test_handler_forwards_application_urllib3_logs(with_memory_logger): + handler = BraintrustLogHandler(init_test_logger(__name__)) + record = logging.LogRecord("urllib3.connectionpool", logging.DEBUG, __file__, 1, "request", (), None) + + handler.handle(record) + + [row] = with_memory_logger.pop() + assert row["output"] == "request" + assert row["metadata"]["logger.name"] == "urllib3.connectionpool" + + +def test_handler_ignores_internal_logs_before_acquiring_lock(): + handler = BraintrustLogHandler(MagicMock()) + record = logging.LogRecord("urllib3.connectionpool", logging.DEBUG, __file__, 1, "internal", (), None) + connection = HTTPConnection("") + connection.session.get = MagicMock(side_effect=lambda *_args, **_kwargs: handler.handle(record)) + executor = concurrent.futures.ThreadPoolExecutor(max_workers=1) + + handler.acquire() + future = executor.submit(connection.get, "https://api.braintrust.dev") + try: + assert future.result(timeout=1) is False + finally: + handler.release() + executor.shutdown(wait=True) diff --git a/py/src/braintrust/type_tests/test_metadata_types.py b/py/src/braintrust/type_tests/test_metadata_types.py index f00a8d1d..fa923419 100644 --- a/py/src/braintrust/type_tests/test_metadata_types.py +++ b/py/src/braintrust/type_tests/test_metadata_types.py @@ -18,11 +18,28 @@ def dict(self, *, exclude_none: bool = False) -> Mapping[str, Any]: def accepts_logger_metadata(logger: Logger) -> None: mapping_metadata: Mapping[str, Any] = {"user_id": "user-1"} + dict_metadata: dict[str, Any] = {"user_id": "user-1"} logger.log(metadata=mapping_metadata) logger.log(metadata=PydanticV2Metadata()) logger.log(metadata=PydanticV1Metadata()) + logger.emit_log(body="message", level="info", metadata=dict_metadata) + logger.trace("message", metadata=dict_metadata) + logger.debug("message", metadata=dict_metadata) + logger.info("message", metadata=dict_metadata) + logger.warn("message", metadata=dict_metadata) + logger.error("message", metadata=dict_metadata) + logger.fatal("message", metadata=dict_metadata) + + logger.emit_log("User {user_id}", "info", metadata=dict_metadata, user_id="user-1") + logger.trace("User {user_id}", metadata=dict_metadata, user_id="user-1") + logger.debug("User {user_id}", metadata=dict_metadata, user_id="user-1") + logger.info("User {user_id}", metadata=dict_metadata, user_id="user-1") + logger.warn("User {user_id}", metadata=dict_metadata, user_id="user-1") + logger.error("User {user_id}", metadata=dict_metadata, user_id="user-1") + logger.fatal("User {user_id}", metadata=dict_metadata, user_id="user-1") + logger.log_feedback(id="event-id", metadata=mapping_metadata) logger.log_feedback(id="event-id", metadata=PydanticV2Metadata()) logger.log_feedback(id="event-id", metadata=PydanticV1Metadata()) diff --git a/py/src/braintrust/type_tests/test_public_exports.py b/py/src/braintrust/type_tests/test_public_exports.py index 928f6716..0702853f 100644 --- a/py/src/braintrust/type_tests/test_public_exports.py +++ b/py/src/braintrust/type_tests/test_public_exports.py @@ -10,6 +10,7 @@ import braintrust import pytest from braintrust import ( + BraintrustLogHandler, auto_instrument, setup_ai_sdk, setup_pydantic_ai, @@ -21,6 +22,7 @@ _PUBLIC_SYMBOLS = [ + ("BraintrustLogHandler", BraintrustLogHandler), ("auto_instrument", auto_instrument), ("wrap_anthropic", wrap_anthropic), ("wrap_litellm", wrap_litellm),