diff --git a/py/src/braintrust/logger.py b/py/src/braintrust/logger.py index f5ffdb28..2213fcdb 100644 --- a/py/src/braintrust/logger.py +++ b/py/src/braintrust/logger.py @@ -131,6 +131,23 @@ # 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"] +_OTEL_LOG_LEVELS: dict[LogLevel, int] = { + "trace": 1, + "debug": 5, + "info": 9, + "warn": 13, + "error": 17, + "fatal": 21, +} + + +class _LogTemplateParameters(dict[str, object]): + """Preserve placeholders whose values were not provided.""" + + def __missing__(self, key: str) -> str: + return "{" + key + "}" + @dataclasses.dataclass class Logs3OverflowInputRow: @@ -5854,6 +5871,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: @@ -5932,6 +5950,112 @@ 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. + + :param body: The log body. May be 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. + """ + if level not in _OTEL_LOG_LEVELS: + valid_levels = ", ".join(_OTEL_LOG_LEVELS) + raise ValueError(f"Invalid log level {level!r}. Expected one of: {valid_levels}") + + rendered_body = body + rendered_metadata = metadata + if 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 + + captured_at = time.time() + span_info = self.state.context_manager.get_current_span_info() + severity_number = _OTEL_LOG_LEVELS[level] + span = self._start_span_impl( + name="Log", + type=SpanTypeAttribute.LOG, + 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=rendered_body, + error=( + rendered_body + if severity_number >= _OTEL_LOG_LEVELS["error"] and isinstance(rendered_body, str) + else None + ), + metadata=rendered_metadata, + context={ + "otel": { + "signal": "logs", + "log": { + "time_unix_nano": str(round(captured_at * 1_000_000_000)), + "severity_number": severity_number, + "severity_text": level.upper(), + }, + } + }, + ) + span.end(end_time=captured_at) + + 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 log at OpenTelemetry TRACE severity.""" + 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 log at OpenTelemetry DEBUG severity.""" + 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 a log at OpenTelemetry INFO severity.""" + 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 log at OpenTelemetry WARN severity.""" + 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 a log at OpenTelemetry ERROR severity.""" + 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 log at OpenTelemetry FATAL severity.""" + return self.emit_log(body=body, level="fatal", metadata=metadata, **parameters) + def log_feedback( self, id: str, 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 1b2aca0f..2b45ee84 100644 --- a/py/src/braintrust/span_types.py +++ b/py/src/braintrust/span_types.py @@ -18,6 +18,7 @@ class SpanTypeAttribute(str, Enum): PREPROCESSOR = "preprocessor" CLASSIFIER = "classifier" REVIEW = "review" + LOG = "log" class SpanPurpose(str, Enum): diff --git a/py/src/braintrust/test_logger.py b/py/src/braintrust/test_logger.py index 7f85eef3..2e77c272 100644 --- a/py/src/braintrust/test_logger.py +++ b/py/src/braintrust/test_logger.py @@ -1396,6 +1396,158 @@ 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 first["error"] == "Payment failed" + assert first["metadata"] == {"payment_id": "pay_123"} + assert first["span_attributes"]["name"] == "Log" + assert first["span_attributes"]["type"] == "log" + assert first["metrics"]["start"] == first["metrics"]["end"] + assert first["context"]["otel"]["signal"] == "logs" + assert first["context"]["otel"]["log"] == { + "time_unix_nano": str(round(first["metrics"]["start"] * 1_000_000_000)), + "severity_number": 17, + "severity_text": "ERROR", + } + assert "error" not in second + assert second["context"]["otel"]["log"]["severity_number"] == 9 + + +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["context"]["otel"]["log"]["severity_number"] == 5 + + +@pytest.mark.parametrize( + ("level", "severity_number"), + [("trace", 1), ("debug", 5), ("info", 9), ("warn", 13), ("error", 17), ("fatal", 21)], +) +def test_logger_emit_log_maps_otel_log_levels(with_memory_logger, level, severity_number): + test_logger = init_test_logger(__name__) + + test_logger.emit_log(body="message", level=level) + + [row] = with_memory_logger.pop() + assert row["context"]["otel"]["log"]["severity_number"] == severity_number + assert row["context"]["otel"]["log"]["severity_text"] == level.upper() + + +@pytest.mark.parametrize( + ("method_name", "severity_number"), + [("trace", 1), ("debug", 5), ("info", 9), ("warn", 13), ("error", 17), ("fatal", 21)], +) +def test_logger_log_level_helpers(with_memory_logger, method_name, severity_number): + 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["context"]["otel"]["log"]["severity_number"] == severity_number + + +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}", + } + + +def test_logger_error_uses_rendered_template_as_error(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 row["error"] == "Payment pay-123 failed" + + +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") + + +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" + + +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/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())