diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index 362be2146e..0fa017a2ed 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2153,23 +2153,24 @@ def _capture_messages( finish_reason: FinishReason | None = None, ) -> None: """Log messages with extra information.""" - from ._types import normalize_messages + from ._types import normalize_messages, prepend_instructions_to_messages normalized_messages = normalize_messages(messages) - otel_messages: list[dict[str, Any]] = [] - for index, message in enumerate(normalized_messages): - # Reuse the otel message representation for logging instead of calling to_dict() - # to avoid expensive Pydantic serialization overhead - otel_message = _to_otel_message(message) + # For logging: prepend framework instructions as messages so the log record + # mirrors the full message list as sent to the provider. + log_messages = prepend_instructions_to_messages(normalized_messages, system_instructions) + for index, message in enumerate(log_messages): logger.info( - otel_message, + _to_otel_message(message), extra={ OtelAttr.EVENT_NAME: OtelAttr.CHOICE if output else ROLE_EVENT_MAP.get(message.role), OtelAttr.PROVIDER_NAME: provider_name, MessageListTimestampFilter.INDEX_KEY: index, }, ) - otel_messages.append(otel_message) + # For the span attribute, only include the original chat history so that + # framework/options instructions are not duplicated into gen_ai.input.messages. + otel_messages: list[dict[str, Any]] = [_to_otel_message(message) for message in normalized_messages] if finish_reason: otel_messages[-1]["finish_reason"] = FINISH_REASON_MAP[finish_reason] span.set_attribute( diff --git a/python/packages/core/tests/core/test_observability.py b/python/packages/core/tests/core/test_observability.py index d4403043af..1966c7164b 100644 --- a/python/packages/core/tests/core/test_observability.py +++ b/python/packages/core/tests/core/test_observability.py @@ -3019,10 +3019,10 @@ async def test_system_instructions_preserves_non_ascii_characters(span_exporter: assert [msg.get("role") for msg in input_messages] == ["user"] -def test_capture_messages_keeps_framework_instructions_out_of_logs_and_span_messages( +def test_capture_messages_logs_prepended_instructions_excludes_them_from_span( span_exporter: InMemorySpanExporter, ): - """Test separate framework instructions do not appear in chat-history logs or span messages.""" + """Test framework instructions are logged as prepended messages but excluded from the span attribute.""" import json from opentelemetry import trace @@ -3043,21 +3043,22 @@ def test_capture_messages_keeps_framework_instructions_out_of_logs_and_span_mess spans = span_exporter.get_finished_spans() assert len(spans) == 1 + # Span attribute must not contain the framework instruction. input_messages = json.loads(spans[0].attributes[OtelAttr.INPUT_MESSAGES]) assert [msg.get("role") for msg in input_messages] == ["user"] - assert mock_logger_info.call_count == 1, f"Expected 1 log call, got {mock_logger_info.call_count}" - (first_call,) = mock_logger_info.call_args_list - assert first_call.args - logged_message = first_call.args[0] - assert logged_message["role"] == "user" - assert logged_message["parts"][0]["content"] == "Test" + # Logging path must include the prepended framework instruction. + assert mock_logger_info.call_count == 2, f"Expected 2 log calls, got {mock_logger_info.call_count}" + logged_messages = [call.args[0] for call in mock_logger_info.call_args_list] + assert [msg["role"] for msg in logged_messages] == ["system", "user"] + assert logged_messages[0]["parts"][0]["content"] == "Framework system instruction" + assert logged_messages[1]["parts"][0]["content"] == "Test" -def test_capture_messages_logs_only_chat_history_when_framework_instructions_are_separate( +def test_capture_messages_logs_prepended_instructions_when_chat_history_has_system_message( span_exporter: InMemorySpanExporter, ): - """Test chat-history logging preserves original system messages without prepending framework instructions.""" + """Test framework instructions are prepended in logs; original system message stays in span attribute.""" import json from opentelemetry import trace @@ -3081,14 +3082,17 @@ def test_capture_messages_logs_only_chat_history_when_framework_instructions_are spans = span_exporter.get_finished_spans() assert len(spans) == 1 + # Span attribute keeps the original chat history (including the original system message). input_messages = json.loads(spans[0].attributes[OtelAttr.INPUT_MESSAGES]) assert [msg.get("role") for msg in input_messages] == ["system", "user"] - assert mock_logger_info.call_count == 2, f"Expected 2 log calls, got {mock_logger_info.call_count}" + # Logging path includes the prepended framework instruction before the chat history. + assert mock_logger_info.call_count == 3, f"Expected 3 log calls, got {mock_logger_info.call_count}" logged_messages = [call.args[0] for call in mock_logger_info.call_args_list] - assert [msg["role"] for msg in logged_messages] == ["system", "user"] - assert logged_messages[0]["parts"][0]["content"] == "Original system message" - assert logged_messages[1]["parts"][0]["content"] == "Test" + assert [msg["role"] for msg in logged_messages] == ["system", "system", "user"] + assert logged_messages[0]["parts"][0]["content"] == "Framework system instruction" + assert logged_messages[1]["parts"][0]["content"] == "Original system message" + assert logged_messages[2]["parts"][0]["content"] == "Test" @pytest.mark.parametrize("enable_sensitive_data", [True], indirect=True)