Skip to content

Commit f763477

Browse files
nikhilNavanikhilc-microsoftCopilotCopilot
authored
Logging for better visibility when using the exporter (#26)
* add logging to important files * add unit tests for logging * Update tests/observability/core/test_record_attributes.py Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> * Update tests/observability/core/test_record_attributes.py Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> * Refactor: Extract duplicated response truncation logic into helper method (#27) * Initial plan * Extract duplicated truncation logic into helper function Co-authored-by: nikhilNava <211831449+nikhilNava@users.noreply.github.com> --------- Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com> Co-authored-by: nikhilNava <211831449+nikhilNava@users.noreply.github.com> * Remove print statements from unit tests (#28) * Initial plan * Remove print statements from unit tests Co-authored-by: nikhilNava <211831449+nikhilNava@users.noreply.github.com> --------- Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com> Co-authored-by: nikhilNava <211831449+nikhilNava@users.noreply.github.com> * Change logging level from debug to info for observability telemetry operations (#29) * Initial plan * Change logger.debug to logger.info for better visibility Co-authored-by: nikhilNava <211831449+nikhilNava@users.noreply.github.com> --------- Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com> Co-authored-by: nikhilNava <211831449+nikhilNava@users.noreply.github.com> --------- Co-authored-by: Nikhil Chitlur Navakiran (from Dev Box) <nikhilc@microsoft.com> Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com> Co-authored-by: Copilot <198982749+Copilot@users.noreply.github.com> Co-authored-by: nikhilNava <211831449+nikhilNava@users.noreply.github.com>
1 parent b255a17 commit f763477

6 files changed

Lines changed: 246 additions & 16 deletions

File tree

‎libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/config.py‎

Lines changed: 7 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,8 @@
1414
from .exporters.utils import is_agent365_exporter_enabled
1515
from .trace_processor.span_processor import SpanProcessor
1616

17+
DEFAULT_LOGGER_NAME = __name__
18+
1719

1820
class TelemetryManager:
1921
"""
@@ -46,7 +48,7 @@ def configure(
4648
self,
4749
service_name: str,
4850
service_namespace: str,
49-
logger_name: str = "agent365",
51+
logger_name: str = DEFAULT_LOGGER_NAME,
5052
token_resolver: Callable[[str, str], str | None] | None = None,
5153
cluster_category: str = "prod",
5254
**kwargs: Any,
@@ -158,11 +160,11 @@ def get_tracer(self, name: str | None = None, version: str | None = None):
158160
to call `configure(...)` during application startup so the tracer
159161
returned is backed by the configured TracerProvider.
160162
161-
:param name: Optional tracer name. Defaults to 'agent365' when not provided.
163+
:param name: Optional tracer name. Defaults to 'microsoft_agents_a365.observability.core' when not provided.
162164
:param version: Optional tracer version.
163165
:return: An OpenTelemetry Tracer instance.
164166
"""
165-
tracer_name = name or "agent365"
167+
tracer_name = name or DEFAULT_LOGGER_NAME
166168
if self._tracer_provider is None:
167169
# Not configured — return whatever tracer OpenTelemetry provides (no-op)
168170
self._logger.warning(
@@ -192,7 +194,7 @@ def get_tracer_provider(self):
192194
def configure(
193195
service_name: str,
194196
service_namespace: str,
195-
logger_name: str = "agent365",
197+
logger_name: str = DEFAULT_LOGGER_NAME,
196198
token_resolver: Callable[[str, str], str | None] | None = None,
197199
cluster_category: str = "prod",
198200
**kwargs: Any,
@@ -228,7 +230,7 @@ def get_tracer(name: str | None = None, version: str | None = None):
228230
"""
229231
Return a tracer tied to the TracerProvider configured by the SDK.
230232
231-
:param name: Optional tracer name. If omitted, defaults to 'agent365'.
233+
:param name: Optional tracer name. If omitted, defaults to 'microsoft_agents_a365.observability.core'.
232234
:param version: Optional tracer version.
233235
:return: An OpenTelemetry Tracer (may be a no-op tracer if SDK isn't configured).
234236
"""

‎libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/exporters/agent365_exporter.py‎

Lines changed: 68 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@
55
from __future__ import annotations
66

77
import json
8+
import logging
89
import threading
910
import time
1011
from collections.abc import Callable, Sequence
@@ -30,6 +31,9 @@
3031
DEFAULT_HTTP_TIMEOUT_SECONDS = 30.0
3132
DEFAULT_MAX_RETRIES = 3
3233

34+
# Create logger for this module - inherits from 'microsoft_agents_a365.observability.core'
35+
logger = logging.getLogger(__name__)
36+
3337

3438
class Agent365Exporter(SpanExporter):
3539
"""
@@ -65,8 +69,15 @@ def export(self, spans: Sequence[ReadableSpan]) -> SpanExportResult:
6569
groups = partition_by_identity(spans)
6670
if not groups:
6771
# No spans with identity; treat as success
72+
logger.info("No spans with tenant/agent identity found; nothing exported.")
6873
return SpanExportResult.SUCCESS
6974

75+
# Debug: Log number of groups and total span count
76+
total_spans = sum(len(activities) for activities in groups.values())
77+
logger.info(
78+
f"Found {len(groups)} identity groups with {total_spans} total spans to export"
79+
)
80+
7081
any_failure = False
7182
for (tenant_id, agent_id), activities in groups.items():
7283
payload = self._build_export_request(activities)
@@ -82,13 +93,25 @@ def export(self, spans: Sequence[ReadableSpan]) -> SpanExportResult:
8293
)
8394
url = f"https://{endpoint}{endpoint_path}?api-version=1"
8495

96+
# Debug: Log endpoint being used
97+
logger.info(
98+
f"Exporting {len(activities)} spans to endpoint: {url} "
99+
f"(tenant: {tenant_id}, agent: {agent_id})"
100+
)
101+
85102
headers = {"content-type": "application/json"}
86103
try:
87104
token = self._token_resolver(agent_id, tenant_id)
88105
if token:
89106
headers["authorization"] = f"Bearer {token}"
90-
except Exception:
107+
logger.info(f"Token resolved successfully for agent {agent_id}")
108+
else:
109+
logger.info(f"No token returned for agent {agent_id}")
110+
except Exception as e:
91111
# If token resolution fails, treat as failure for this group
112+
logger.error(
113+
f"Token resolution failed for agent {agent_id}, tenant {tenant_id}: {e}"
114+
)
92115
any_failure = True
93116
continue
94117

@@ -99,8 +122,9 @@ def export(self, spans: Sequence[ReadableSpan]) -> SpanExportResult:
99122

100123
return SpanExportResult.FAILURE if any_failure else SpanExportResult.SUCCESS
101124

102-
except Exception:
125+
except Exception as e:
103126
# Exporters should not raise; signal failure.
127+
logger.error(f"Export failed with exception: {e}")
104128
return SpanExportResult.FAILURE
105129

106130
def shutdown(self) -> None:
@@ -118,6 +142,13 @@ def force_flush(self, timeout_millis: int = 30000) -> bool:
118142

119143
# ------------- HTTP helper ----------------------
120144

145+
@staticmethod
146+
def _truncate_text(text: str, max_length: int) -> str:
147+
"""Truncate text to a maximum length, adding '...' if truncated."""
148+
if len(text) > max_length:
149+
return text[:max_length] + "..."
150+
return text
151+
121152
def _post_with_retries(self, url: str, body: str, headers: dict[str, str]) -> bool:
122153
for attempt in range(DEFAULT_MAX_RETRIES + 1):
123154
try:
@@ -127,20 +158,54 @@ def _post_with_retries(self, url: str, body: str, headers: dict[str, str]) -> bo
127158
headers=headers,
128159
timeout=DEFAULT_HTTP_TIMEOUT_SECONDS,
129160
)
161+
162+
# Extract correlation ID from response headers for logging
163+
correlation_id = (
164+
resp.headers.get("x-ms-correlation-id")
165+
or resp.headers.get("request-id")
166+
or "N/A"
167+
)
168+
130169
# 2xx => success
131170
if 200 <= resp.status_code < 300:
171+
logger.info(
172+
f"HTTP {resp.status_code} success on attempt {attempt + 1}. "
173+
f"Correlation ID: {correlation_id}. "
174+
f"Response: {self._truncate_text(resp.text, 200)}"
175+
)
132176
return True
133177

178+
# Log non-success responses
179+
response_text = self._truncate_text(resp.text, 500)
180+
134181
# Retry transient
135182
if resp.status_code in (408, 429) or 500 <= resp.status_code < 600:
136183
if attempt < DEFAULT_MAX_RETRIES:
137184
time.sleep(0.2 * (attempt + 1))
138185
continue
186+
# Final attempt failed
187+
logger.error(
188+
f"HTTP {resp.status_code} final failure after {DEFAULT_MAX_RETRIES + 1} attempts. "
189+
f"Correlation ID: {correlation_id}. "
190+
f"Response: {response_text}"
191+
)
192+
else:
193+
# Non-retryable error
194+
logger.error(
195+
f"HTTP {resp.status_code} non-retryable error. "
196+
f"Correlation ID: {correlation_id}. "
197+
f"Response: {response_text}"
198+
)
139199
return False
140-
except requests.RequestException:
200+
201+
except requests.RequestException as e:
141202
if attempt < DEFAULT_MAX_RETRIES:
142203
time.sleep(0.2 * (attempt + 1))
143204
continue
205+
# Final attempt failed
206+
logger.error(
207+
f"Request failed after {DEFAULT_MAX_RETRIES + 1} attempts with exception: {e}"
208+
)
144209
return False
145210
return False
146211

‎libraries/microsoft-agents-a365-observability-core/microsoft_agents_a365/observability/core/opentelemetry_scope.py‎

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@
22

33
# Base class for OpenTelemetry tracing scopes.
44

5+
import logging
56
import os
67
import time
78
from threading import Lock
@@ -35,6 +36,9 @@
3536
from .agent_details import AgentDetails
3637
from .tenant_details import TenantDetails
3738

39+
# Create logger for this module - inherits from 'microsoft_agents_a365.observability.core'
40+
logger = logging.getLogger(__name__)
41+
3842

3943
class OpenTelemetryScope:
4044
"""Base class for OpenTelemetry tracing scopes in the SDK."""
@@ -104,6 +108,13 @@ def __init__(
104108
activity_name, kind=activity_kind, context=current_context
105109
)
106110

111+
# Log span creation
112+
if self._span:
113+
span_id = f"{self._span.context.span_id:016x}" if self._span.context else "unknown"
114+
logger.info(f"Span started: '{activity_name}' ({span_id})")
115+
else:
116+
logger.error(f"Failed to create span: '{activity_name}' - tracer returned None")
117+
107118
# Set common tags
108119
if self._span:
109120
self._span.set_attribute(GEN_AI_SYSTEM_KEY, GEN_AI_SYSTEM_VALUE)
@@ -210,6 +221,9 @@ def _end(self) -> None:
210221
"""End the span and record metrics."""
211222
if self._span and self._is_telemetry_enabled() and not self._has_ended:
212223
self._has_ended = True
224+
span_id = f"{self._span.context.span_id:016x}" if self._span.context else "unknown"
225+
logger.info(f"Span ended: '{self._span.name}' ({span_id})")
226+
213227
self._span.end()
214228

215229
def __enter__(self):

‎tests/observability/core/test_agent365_exporter.py‎

Lines changed: 85 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -287,6 +287,91 @@ def test_default_endpoint_path_when_s2s_disabled(self):
287287
self.assertEqual(headers["authorization"], "Bearer test_token_123")
288288
self.assertEqual(headers["content-type"], "application/json")
289289

290+
@patch("microsoft_agents_a365.observability.core.exporters.agent365_exporter.logger")
291+
@patch(
292+
"microsoft_agents_a365.observability.core.exporters.agent365_exporter.PowerPlatformApiDiscovery"
293+
)
294+
def test_export_logging(self, mock_discovery, mock_logger):
295+
"""Test that the exporter logs appropriate messages during export."""
296+
# Mock the discovery service
297+
mock_discovery_instance = Mock()
298+
mock_discovery_instance.get_tenant_island_cluster_endpoint.return_value = (
299+
"test-endpoint.com"
300+
)
301+
mock_discovery.return_value = mock_discovery_instance
302+
303+
# Mock successful HTTP response
304+
with patch("requests.Session.post") as mock_post:
305+
mock_response = Mock()
306+
mock_response.status_code = 200
307+
mock_response.text = "success"
308+
mock_response.headers = {"x-ms-correlation-id": "test-correlation-123"}
309+
mock_post.return_value = mock_response
310+
311+
# Create test spans
312+
spans = [
313+
self._create_mock_span(
314+
name="test_span_1",
315+
attributes={
316+
TENANT_ID_KEY: "test-tenant-123",
317+
GEN_AI_AGENT_ID_KEY: "test-agent-456",
318+
},
319+
),
320+
self._create_mock_span(
321+
name="test_span_2",
322+
attributes={
323+
TENANT_ID_KEY: "test-tenant-123",
324+
GEN_AI_AGENT_ID_KEY: "test-agent-456",
325+
},
326+
),
327+
]
328+
329+
# Export spans
330+
result = self.exporter.export(spans)
331+
332+
# Verify export succeeded
333+
self.assertEqual(result, SpanExportResult.SUCCESS)
334+
335+
# Verify logging calls
336+
expected_log_calls = [
337+
# Should log groups found
338+
unittest.mock.call.info("Found 1 identity groups with 2 total spans to export"),
339+
# Should log endpoint being used
340+
unittest.mock.call.info(
341+
"Exporting 2 spans to endpoint: https://test-endpoint.com/maven/agent365/agents/test-agent-456/traces?api-version=1 "
342+
"(tenant: test-tenant-123, agent: test-agent-456)"
343+
),
344+
# Should log token resolution success
345+
unittest.mock.call.info("Token resolved successfully for agent test-agent-456"),
346+
# Should log HTTP success
347+
unittest.mock.call.info(
348+
"HTTP 200 success on attempt 1. Correlation ID: test-correlation-123. Response: success"
349+
),
350+
]
351+
352+
# Check that all expected info calls were made
353+
for expected_call in expected_log_calls:
354+
self.assertIn(expected_call, mock_logger.info.call_args_list)
355+
356+
@patch("microsoft_agents_a365.observability.core.exporters.agent365_exporter.logger")
357+
def test_export_error_logging(self, mock_logger):
358+
"""Test that the exporter logs errors appropriately."""
359+
# Create spans without tenant/agent identity - explicitly pass None values
360+
spans = [
361+
self._create_mock_span(name="test_span", attributes={}, tenant_id=None, agent_id=None)
362+
]
363+
364+
# Export spans (should succeed but log no identity)
365+
result = self.exporter.export(spans)
366+
367+
# Verify export succeeded (no identity spans are treated as success)
368+
self.assertEqual(result, SpanExportResult.SUCCESS)
369+
370+
# Verify info log for no identity
371+
mock_logger.info.assert_called_with(
372+
"No spans with tenant/agent identity found; nothing exported."
373+
)
374+
290375

291376
if __name__ == "__main__":
292377
unittest.main()

0 commit comments

Comments
 (0)