From 7566e3e382cf25dc54782bf57f13551faec9a4b3 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 21:13:53 +0000 Subject: [PATCH 01/16] Initial plan From 30174f9a5c53bd418c284ff86982d8a849c4dec0 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 21:17:37 +0000 Subject: [PATCH 02/16] Fix duplicated system instructions in Python telemetry --- .../packages/core/agent_framework/observability.py | 14 ++++++++------ .../packages/core/tests/core/test_observability.py | 10 ++++++++-- 2 files changed, 16 insertions(+), 8 deletions(-) diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index 022008c05b..71dbf316ec 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2155,13 +2155,15 @@ def _capture_messages( """Log messages with extra information.""" from ._types import normalize_messages, prepend_instructions_to_messages - prepped = prepend_instructions_to_messages(normalize_messages(messages), system_instructions) - otel_messages: list[dict[str, Any]] = [] + normalized_messages = normalize_messages(messages) + prepped = prepend_instructions_to_messages(normalized_messages, system_instructions) + span_messages: list[dict[str, Any]] = [] for index, message in enumerate(prepped): + otel_message = _to_otel_message(message) + if index >= len(prepped) - len(normalized_messages): + span_messages.append(otel_message) # Reuse the otel message representation for logging instead of calling to_dict() # to avoid expensive Pydantic serialization overhead - otel_message = _to_otel_message(message) - otel_messages.append(otel_message) logger.info( otel_message, extra={ @@ -2171,9 +2173,9 @@ def _capture_messages( }, ) if finish_reason: - otel_messages[-1]["finish_reason"] = FINISH_REASON_MAP[finish_reason] + span_messages[-1]["finish_reason"] = FINISH_REASON_MAP[finish_reason] span.set_attribute( - OtelAttr.OUTPUT_MESSAGES if output else OtelAttr.INPUT_MESSAGES, json.dumps(otel_messages, ensure_ascii=False) + OtelAttr.OUTPUT_MESSAGES if output else OtelAttr.INPUT_MESSAGES, json.dumps(span_messages, ensure_ascii=False) ) if system_instructions: if not isinstance(system_instructions, list): diff --git a/python/packages/core/tests/core/test_observability.py b/python/packages/core/tests/core/test_observability.py index 6185bccd44..7674c70800 100644 --- a/python/packages/core/tests/core/test_observability.py +++ b/python/packages/core/tests/core/test_observability.py @@ -290,9 +290,9 @@ async def test_chat_client_observability_with_instructions( assert len(system_instructions) == 1 assert system_instructions[0]["content"] == "You are a helpful assistant." - # Verify input_messages contains system message + # Verify input_messages excludes system instructions input_messages = json.loads(span.attributes[OtelAttr.INPUT_MESSAGES]) - assert any(msg.get("role") == "system" for msg in input_messages) + assert [msg.get("role") for msg in input_messages] == ["user"] @pytest.mark.parametrize("enable_sensitive_data", [True], indirect=True) @@ -2981,6 +2981,9 @@ async def test_system_instructions_preserves_non_ascii_characters(span_exporter: system_instructions = json.loads(system_instructions_json) assert system_instructions[0]["content"] == chinese_text + input_messages = json.loads(span.attributes[OtelAttr.INPUT_MESSAGES]) + assert [msg.get("role") for msg in input_messages] == ["user"] + @pytest.mark.parametrize("enable_sensitive_data", [True], indirect=True) async def test_tool_arguments_preserves_non_ascii_characters(span_exporter: InMemorySpanExporter): @@ -3104,6 +3107,9 @@ async def test_agent_instructions_from_default_options( assert len(system_instructions) == 1 assert system_instructions[0]["content"] == "Default system instructions." + input_messages = json.loads(span.attributes[OtelAttr.INPUT_MESSAGES]) + assert [msg.get("role") for msg in input_messages] == ["user"] + @pytest.mark.parametrize("enable_sensitive_data", [True], indirect=True) async def test_agent_instructions_from_options_override( From 12c01642afb6169ffad5215959d76f407c9098cb Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 21:18:13 +0000 Subject: [PATCH 03/16] Clarify telemetry message filtering --- python/packages/core/agent_framework/observability.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index 71dbf316ec..beded86e12 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2158,9 +2158,10 @@ def _capture_messages( normalized_messages = normalize_messages(messages) prepped = prepend_instructions_to_messages(normalized_messages, system_instructions) span_messages: list[dict[str, Any]] = [] + span_message_start_index = len(prepped) - len(normalized_messages) for index, message in enumerate(prepped): otel_message = _to_otel_message(message) - if index >= len(prepped) - len(normalized_messages): + if index >= span_message_start_index: span_messages.append(otel_message) # Reuse the otel message representation for logging instead of calling to_dict() # to avoid expensive Pydantic serialization overhead From 1b691ae6c7d5cb2d8dd169fdf525df23fd32745b Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 21:33:03 +0000 Subject: [PATCH 04/16] test: cover separate and in-history system messages --- .../core/tests/core/test_observability.py | 65 +++++++++++++++++++ 1 file changed, 65 insertions(+) diff --git a/python/packages/core/tests/core/test_observability.py b/python/packages/core/tests/core/test_observability.py index 7674c70800..55d6edfc34 100644 --- a/python/packages/core/tests/core/test_observability.py +++ b/python/packages/core/tests/core/test_observability.py @@ -324,6 +324,40 @@ async def test_chat_client_streaming_observability_with_instructions( assert len(system_instructions) == 1 assert system_instructions[0]["content"] == "You are a helpful assistant." + input_messages = json.loads(span.attributes[OtelAttr.INPUT_MESSAGES]) + assert [msg.get("role") for msg in input_messages] == ["user"] + + +@pytest.mark.parametrize("enable_sensitive_data", [True], indirect=True) +async def test_chat_client_observability_with_system_message_and_instructions( + mock_chat_client, span_exporter: InMemorySpanExporter, enable_sensitive_data +): + """Test input chat-history system messages stay in input_messages when instructions are separate.""" + import json + + client = mock_chat_client() + + messages = [ + Message(role="system", contents=["Original system message"]), + Message(role="user", contents=["Test message"]), + ] + options = {"model": "Test", "instructions": "Framework system instruction"} + span_exporter.clear() + response = await client.get_response(messages=messages, options=options) + + assert response is not None + spans = span_exporter.get_finished_spans() + assert len(spans) == 1 + span = spans[0] + + system_instructions = json.loads(span.attributes[OtelAttr.SYSTEM_INSTRUCTIONS]) + assert system_instructions == [{"type": "text", "content": "Framework system instruction"}] + + input_messages = json.loads(span.attributes[OtelAttr.INPUT_MESSAGES]) + assert [msg.get("role") for msg in input_messages] == ["system", "user"] + assert input_messages[0]["parts"][0]["content"] == "Original system message" + assert input_messages[1]["parts"][0]["content"] == "Test message" + @pytest.mark.parametrize("enable_sensitive_data", [True], indirect=True) async def test_chat_client_observability_without_instructions( @@ -3111,6 +3145,37 @@ async def test_agent_instructions_from_default_options( assert [msg.get("role") for msg in input_messages] == ["user"] +@pytest.mark.parametrize("enable_sensitive_data", [True], indirect=True) +async def test_agent_instructions_preserve_system_messages_in_history( + mock_chat_agent, span_exporter: InMemorySpanExporter, enable_sensitive_data +): + """Test agent spans keep chat-history system messages separate from framework instructions.""" + import json + + agent = mock_chat_agent() + agent.default_options = {"model": "TestModel", "instructions": "Default system instructions."} + + messages = [ + Message(role="system", contents=["Original system message"]), + Message(role="user", contents=["Test message"]), + ] + span_exporter.clear() + response = await agent.run(messages) + + assert response is not None + spans = span_exporter.get_finished_spans() + assert len(spans) == 1 + span = spans[0] + + system_instructions = json.loads(span.attributes[OtelAttr.SYSTEM_INSTRUCTIONS]) + assert system_instructions == [{"type": "text", "content": "Default system instructions."}] + + input_messages = json.loads(span.attributes[OtelAttr.INPUT_MESSAGES]) + assert [msg.get("role") for msg in input_messages] == ["system", "user"] + assert input_messages[0]["parts"][0]["content"] == "Original system message" + assert input_messages[1]["parts"][0]["content"] == "Test message" + + @pytest.mark.parametrize("enable_sensitive_data", [True], indirect=True) async def test_agent_instructions_from_options_override( mock_chat_agent, span_exporter: InMemorySpanExporter, enable_sensitive_data From 016cc1a80c26c2aa57f668fe3071cae85dec2b26 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 22:03:33 +0000 Subject: [PATCH 05/16] Clarify observability message logging split --- .../core/agent_framework/observability.py | 12 +++---- .../core/tests/core/test_observability.py | 33 +++++++++++++++++++ 2 files changed, 38 insertions(+), 7 deletions(-) diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index beded86e12..6f981b4ada 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2156,13 +2156,11 @@ def _capture_messages( from ._types import normalize_messages, prepend_instructions_to_messages normalized_messages = normalize_messages(messages) - prepped = prepend_instructions_to_messages(normalized_messages, system_instructions) - span_messages: list[dict[str, Any]] = [] - span_message_start_index = len(prepped) - len(normalized_messages) - for index, message in enumerate(prepped): - otel_message = _to_otel_message(message) - if index >= span_message_start_index: - span_messages.append(otel_message) + logging_messages = prepend_instructions_to_messages(normalized_messages, system_instructions) + span_messages = [_to_otel_message(message) for message in normalized_messages] + prepended_count = len(logging_messages) - len(normalized_messages) + for index, message in enumerate(logging_messages): + otel_message = span_messages[index - prepended_count] if index >= prepended_count else _to_otel_message(message) # Reuse the otel message representation for logging instead of calling to_dict() # to avoid expensive Pydantic serialization overhead logger.info( diff --git a/python/packages/core/tests/core/test_observability.py b/python/packages/core/tests/core/test_observability.py index 55d6edfc34..3e9cf40cf9 100644 --- a/python/packages/core/tests/core/test_observability.py +++ b/python/packages/core/tests/core/test_observability.py @@ -3019,6 +3019,39 @@ 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_logs_prepended_instructions_without_serializing_them( + span_exporter: InMemorySpanExporter, +): + """Test prepended instructions still emit log events while span input_messages stays chat-history only.""" + import json + + from opentelemetry import trace + + tracer = trace.get_tracer("test") + span_exporter.clear() + + with ( + patch("agent_framework.observability.logger.info") as mock_logger_info, + tracer.start_as_current_span("test_span") as span, + ): + _capture_messages( + span=span, + provider_name="test_provider", + messages=[Message(role="user", contents=["Test"])], + system_instructions="Framework system instruction", + ) + + spans = span_exporter.get_finished_spans() + assert len(spans) == 1 + input_messages = json.loads(spans[0].attributes[OtelAttr.INPUT_MESSAGES]) + assert [msg.get("role") for msg in input_messages] == ["user"] + + 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" + + @pytest.mark.parametrize("enable_sensitive_data", [True], indirect=True) async def test_tool_arguments_preserves_non_ascii_characters(span_exporter: InMemorySpanExporter): """Test that non-ASCII characters are preserved in tool arguments span attribute.""" From ece3db8cfde14654d5609e255cf4e07cb533a52e Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 22:04:19 +0000 Subject: [PATCH 06/16] Simplify observability logging serialization --- python/packages/core/agent_framework/observability.py | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index 6f981b4ada..8a5ff14bbf 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2158,9 +2158,8 @@ def _capture_messages( normalized_messages = normalize_messages(messages) logging_messages = prepend_instructions_to_messages(normalized_messages, system_instructions) span_messages = [_to_otel_message(message) for message in normalized_messages] - prepended_count = len(logging_messages) - len(normalized_messages) for index, message in enumerate(logging_messages): - otel_message = span_messages[index - prepended_count] if index >= prepended_count else _to_otel_message(message) + otel_message = _to_otel_message(message) # Reuse the otel message representation for logging instead of calling to_dict() # to avoid expensive Pydantic serialization overhead logger.info( From f16a6295fbfc54a24ff294f9b65ecdd46b4a58e7 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 22:04:55 +0000 Subject: [PATCH 07/16] Harden observability regression test --- python/packages/core/tests/core/test_observability.py | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/python/packages/core/tests/core/test_observability.py b/python/packages/core/tests/core/test_observability.py index 3e9cf40cf9..8801d65c65 100644 --- a/python/packages/core/tests/core/test_observability.py +++ b/python/packages/core/tests/core/test_observability.py @@ -3046,7 +3046,11 @@ def test_capture_messages_logs_prepended_instructions_without_serializing_them( input_messages = json.loads(spans[0].attributes[OtelAttr.INPUT_MESSAGES]) assert [msg.get("role") for msg in input_messages] == ["user"] - logged_messages = [call.args[0] for call in mock_logger_info.call_args_list] + assert mock_logger_info.call_count == 2 + first_call, second_call = mock_logger_info.call_args_list + assert first_call.args + assert second_call.args + logged_messages = [first_call.args[0], second_call.args[0]] 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" From f6db62e07bce492f977194788af035852506dcf3 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 22:05:40 +0000 Subject: [PATCH 08/16] Reuse observability span message serialization --- python/packages/core/agent_framework/observability.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index 8a5ff14bbf..7c63581c19 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2158,8 +2158,10 @@ def _capture_messages( normalized_messages = normalize_messages(messages) logging_messages = prepend_instructions_to_messages(normalized_messages, system_instructions) span_messages = [_to_otel_message(message) for message in normalized_messages] + span_message_iter = iter(span_messages) + prepended_count = len(logging_messages) - len(normalized_messages) for index, message in enumerate(logging_messages): - otel_message = _to_otel_message(message) + otel_message = _to_otel_message(message) if index < prepended_count else next(span_message_iter) # Reuse the otel message representation for logging instead of calling to_dict() # to avoid expensive Pydantic serialization overhead logger.info( From ecf5341ca0d945f43775344b63f7cd673dfd1400 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 22:06:35 +0000 Subject: [PATCH 09/16] Clarify observability logging loops --- .../core/agent_framework/observability.py | 15 ++++++++++++--- .../core/tests/core/test_observability.py | 2 +- 2 files changed, 13 insertions(+), 4 deletions(-) diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index 7c63581c19..391c77a3c5 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2158,10 +2158,9 @@ def _capture_messages( normalized_messages = normalize_messages(messages) logging_messages = prepend_instructions_to_messages(normalized_messages, system_instructions) span_messages = [_to_otel_message(message) for message in normalized_messages] - span_message_iter = iter(span_messages) prepended_count = len(logging_messages) - len(normalized_messages) - for index, message in enumerate(logging_messages): - otel_message = _to_otel_message(message) if index < prepended_count else next(span_message_iter) + for index, message in enumerate(logging_messages[:prepended_count]): + otel_message = _to_otel_message(message) # Reuse the otel message representation for logging instead of calling to_dict() # to avoid expensive Pydantic serialization overhead logger.info( @@ -2172,6 +2171,16 @@ def _capture_messages( MessageListTimestampFilter.INDEX_KEY: index, }, ) + for index, message in enumerate(normalized_messages, start=prepended_count): + otel_message = span_messages[index - prepended_count] + logger.info( + otel_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, + }, + ) if finish_reason: span_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 8801d65c65..c139f1a115 100644 --- a/python/packages/core/tests/core/test_observability.py +++ b/python/packages/core/tests/core/test_observability.py @@ -3046,7 +3046,7 @@ def test_capture_messages_logs_prepended_instructions_without_serializing_them( 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 == 2 + assert mock_logger_info.call_count == 2, f"Expected 2 log calls, got {mock_logger_info.call_count}" first_call, second_call = mock_logger_info.call_args_list assert first_call.args assert second_call.args From 40e4a0b0ff27f83330610267dd23f38e23846e96 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 22:07:31 +0000 Subject: [PATCH 10/16] Polish observability message serialization --- python/packages/core/agent_framework/observability.py | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index 391c77a3c5..9d36003bee 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2159,8 +2159,10 @@ def _capture_messages( logging_messages = prepend_instructions_to_messages(normalized_messages, system_instructions) span_messages = [_to_otel_message(message) for message in normalized_messages] prepended_count = len(logging_messages) - len(normalized_messages) - for index, message in enumerate(logging_messages[:prepended_count]): - otel_message = _to_otel_message(message) + prepended_messages = [_to_otel_message(message) for message in logging_messages[:prepended_count]] + for index, (message, otel_message) in enumerate( + zip(logging_messages[:prepended_count], prepended_messages, strict=False) + ): # Reuse the otel message representation for logging instead of calling to_dict() # to avoid expensive Pydantic serialization overhead logger.info( @@ -2171,8 +2173,9 @@ def _capture_messages( MessageListTimestampFilter.INDEX_KEY: index, }, ) - for index, message in enumerate(normalized_messages, start=prepended_count): - otel_message = span_messages[index - prepended_count] + for index, (message, otel_message) in enumerate( + zip(normalized_messages, span_messages, strict=False), start=prepended_count + ): logger.info( otel_message, extra={ From 25ceb87d7255554c194d820e06f1b2fa32537e0a Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 22:08:11 +0000 Subject: [PATCH 11/16] Tighten observability zip checks --- python/packages/core/agent_framework/observability.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index 9d36003bee..42c1fd4308 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2161,7 +2161,7 @@ def _capture_messages( prepended_count = len(logging_messages) - len(normalized_messages) prepended_messages = [_to_otel_message(message) for message in logging_messages[:prepended_count]] for index, (message, otel_message) in enumerate( - zip(logging_messages[:prepended_count], prepended_messages, strict=False) + zip(logging_messages[:prepended_count], prepended_messages, strict=True) ): # Reuse the otel message representation for logging instead of calling to_dict() # to avoid expensive Pydantic serialization overhead @@ -2174,7 +2174,7 @@ def _capture_messages( }, ) for index, (message, otel_message) in enumerate( - zip(normalized_messages, span_messages, strict=False), start=prepended_count + zip(normalized_messages, span_messages, strict=True), start=prepended_count ): logger.info( otel_message, From 84e5a62d8716ba4cb7466a5ba2fea8e5f70db061 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 22:21:17 +0000 Subject: [PATCH 12/16] Refactor observability message capture loop --- .../core/agent_framework/observability.py | 21 +++------- .../core/tests/core/test_observability.py | 38 +++++++++++++++++++ 2 files changed, 43 insertions(+), 16 deletions(-) diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index 42c1fd4308..bd1ae56340 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2157,14 +2157,12 @@ def _capture_messages( normalized_messages = normalize_messages(messages) logging_messages = prepend_instructions_to_messages(normalized_messages, system_instructions) - span_messages = [_to_otel_message(message) for message in normalized_messages] prepended_count = len(logging_messages) - len(normalized_messages) - prepended_messages = [_to_otel_message(message) for message in logging_messages[:prepended_count]] - for index, (message, otel_message) in enumerate( - zip(logging_messages[:prepended_count], prepended_messages, strict=True) - ): + span_messages = [] + for index, message in enumerate(logging_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) logger.info( otel_message, extra={ @@ -2173,17 +2171,8 @@ def _capture_messages( MessageListTimestampFilter.INDEX_KEY: index, }, ) - for index, (message, otel_message) in enumerate( - zip(normalized_messages, span_messages, strict=True), start=prepended_count - ): - logger.info( - otel_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, - }, - ) + if index >= prepended_count: + span_messages.append(otel_message) if finish_reason: span_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 c139f1a115..28223dbbec 100644 --- a/python/packages/core/tests/core/test_observability.py +++ b/python/packages/core/tests/core/test_observability.py @@ -3056,6 +3056,44 @@ def test_capture_messages_logs_prepended_instructions_without_serializing_them( assert logged_messages[1]["parts"][0]["content"] == "Test" +def test_capture_messages_logs_framework_and_chat_history_system_messages_once( + span_exporter: InMemorySpanExporter, +): + """Test framework instructions and chat-history system messages each log once.""" + import json + + from opentelemetry import trace + + tracer = trace.get_tracer("test") + span_exporter.clear() + + with ( + patch("agent_framework.observability.logger.info") as mock_logger_info, + tracer.start_as_current_span("test_span") as span, + ): + _capture_messages( + span=span, + provider_name="test_provider", + messages=[ + Message(role="system", contents=["Original system message"]), + Message(role="user", contents=["Test"]), + ], + system_instructions="Framework system instruction", + ) + + spans = span_exporter.get_finished_spans() + assert len(spans) == 1 + 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 == 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", "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) async def test_tool_arguments_preserves_non_ascii_characters(span_exporter: InMemorySpanExporter): """Test that non-ASCII characters are preserved in tool arguments span attribute.""" From 5e039d1251038c7c81c49f7d463191004322c9cc Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 22:34:00 +0000 Subject: [PATCH 13/16] Fix telemetry logging for separate system instructions --- .../core/agent_framework/observability.py | 9 ++---- .../core/tests/core/test_observability.py | 29 +++++++++---------- 2 files changed, 16 insertions(+), 22 deletions(-) diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index bd1ae56340..422f9e3a9d 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2153,13 +2153,11 @@ def _capture_messages( finish_reason: FinishReason | None = None, ) -> None: """Log messages with extra information.""" - from ._types import normalize_messages, prepend_instructions_to_messages + from ._types import normalize_messages normalized_messages = normalize_messages(messages) - logging_messages = prepend_instructions_to_messages(normalized_messages, system_instructions) - prepended_count = len(logging_messages) - len(normalized_messages) span_messages = [] - for index, message in enumerate(logging_messages): + 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) @@ -2171,8 +2169,7 @@ def _capture_messages( MessageListTimestampFilter.INDEX_KEY: index, }, ) - if index >= prepended_count: - span_messages.append(otel_message) + span_messages.append(otel_message) if finish_reason: span_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 28223dbbec..d4403043af 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_logs_prepended_instructions_without_serializing_them( +def test_capture_messages_keeps_framework_instructions_out_of_logs_and_span_messages( span_exporter: InMemorySpanExporter, ): - """Test prepended instructions still emit log events while span input_messages stays chat-history only.""" + """Test separate framework instructions do not appear in chat-history logs or span messages.""" import json from opentelemetry import trace @@ -3046,20 +3046,18 @@ def test_capture_messages_logs_prepended_instructions_without_serializing_them( 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 == 2, f"Expected 2 log calls, got {mock_logger_info.call_count}" - first_call, second_call = mock_logger_info.call_args_list + 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 - assert second_call.args - logged_messages = [first_call.args[0], second_call.args[0]] - 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" + logged_message = first_call.args[0] + assert logged_message["role"] == "user" + assert logged_message["parts"][0]["content"] == "Test" -def test_capture_messages_logs_framework_and_chat_history_system_messages_once( +def test_capture_messages_logs_only_chat_history_when_framework_instructions_are_separate( span_exporter: InMemorySpanExporter, ): - """Test framework instructions and chat-history system messages each log once.""" + """Test chat-history logging preserves original system messages without prepending framework instructions.""" import json from opentelemetry import trace @@ -3086,12 +3084,11 @@ def test_capture_messages_logs_framework_and_chat_history_system_messages_once( 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 == 3, f"Expected 3 log calls, got {mock_logger_info.call_count}" + 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", "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" + 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" @pytest.mark.parametrize("enable_sensitive_data", [True], indirect=True) From 589fad0876ae0625b400eb0352ba258211442b8a Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Wed, 20 May 2026 22:54:45 +0000 Subject: [PATCH 14/16] Refine observability OTEL message typing --- python/packages/core/agent_framework/observability.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index 422f9e3a9d..362be2146e 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2156,7 +2156,7 @@ def _capture_messages( from ._types import normalize_messages normalized_messages = normalize_messages(messages) - span_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 @@ -2169,11 +2169,11 @@ def _capture_messages( MessageListTimestampFilter.INDEX_KEY: index, }, ) - span_messages.append(otel_message) + otel_messages.append(otel_message) if finish_reason: - span_messages[-1]["finish_reason"] = FINISH_REASON_MAP[finish_reason] + otel_messages[-1]["finish_reason"] = FINISH_REASON_MAP[finish_reason] span.set_attribute( - OtelAttr.OUTPUT_MESSAGES if output else OtelAttr.INPUT_MESSAGES, json.dumps(span_messages, ensure_ascii=False) + OtelAttr.OUTPUT_MESSAGES if output else OtelAttr.INPUT_MESSAGES, json.dumps(otel_messages, ensure_ascii=False) ) if system_instructions: if not isinstance(system_instructions, list): From 5d8565ae01e44918f942710d911ac2d8bed205ac Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 21 May 2026 17:46:10 +0000 Subject: [PATCH 15/16] Restore prepended-instruction logging path in _capture_messages --- .../core/agent_framework/observability.py | 17 +++++----- .../core/tests/core/test_observability.py | 32 +++++++++++-------- 2 files changed, 27 insertions(+), 22 deletions(-) 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) From 068e38327515b46d7c199e48ab7bea5981061938 Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Thu, 21 May 2026 18:03:48 +0000 Subject: [PATCH 16/16] Revert logging change in _capture_messages; keep chat-history-only logging --- .../core/agent_framework/observability.py | 17 +++++----- .../core/tests/core/test_observability.py | 32 ++++++++----------- 2 files changed, 22 insertions(+), 27 deletions(-) diff --git a/python/packages/core/agent_framework/observability.py b/python/packages/core/agent_framework/observability.py index 0fa017a2ed..362be2146e 100644 --- a/python/packages/core/agent_framework/observability.py +++ b/python/packages/core/agent_framework/observability.py @@ -2153,24 +2153,23 @@ def _capture_messages( finish_reason: FinishReason | None = None, ) -> None: """Log messages with extra information.""" - from ._types import normalize_messages, prepend_instructions_to_messages + from ._types import normalize_messages normalized_messages = normalize_messages(messages) - # 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): + 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) logger.info( - _to_otel_message(message), + otel_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, }, ) - # 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] + otel_messages.append(otel_message) 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 1966c7164b..d4403043af 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_logs_prepended_instructions_excludes_them_from_span( +def test_capture_messages_keeps_framework_instructions_out_of_logs_and_span_messages( span_exporter: InMemorySpanExporter, ): - """Test framework instructions are logged as prepended messages but excluded from the span attribute.""" + """Test separate framework instructions do not appear in chat-history logs or span messages.""" import json from opentelemetry import trace @@ -3043,22 +3043,21 @@ def test_capture_messages_logs_prepended_instructions_excludes_them_from_span( 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"] - # 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" + 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" -def test_capture_messages_logs_prepended_instructions_when_chat_history_has_system_message( +def test_capture_messages_logs_only_chat_history_when_framework_instructions_are_separate( span_exporter: InMemorySpanExporter, ): - """Test framework instructions are prepended in logs; original system message stays in span attribute.""" + """Test chat-history logging preserves original system messages without prepending framework instructions.""" import json from opentelemetry import trace @@ -3082,17 +3081,14 @@ def test_capture_messages_logs_prepended_instructions_when_chat_history_has_syst 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"] - # 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}" + 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", "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" + 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" @pytest.mark.parametrize("enable_sensitive_data", [True], indirect=True)