Skip to content

Commit 8fd9d35

Browse files
Kanchan-MicrosoftKanchan-Microsoft
committed
updated
1 parent 33d4660 commit 8fd9d35

3 files changed

Lines changed: 464 additions & 22 deletions

File tree

‎App/backend-api/Microsoft.GS.DPS.Host/API/ChatHost/Chat.cs‎

Lines changed: 244 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -23,27 +23,74 @@ public static void AddAPIs(WebApplication app)
2323
// Generate unique request ID for tracking
2424
var requestId = httpContext.TraceIdentifier;
2525
telemetryHelper.SetActivityTag("requestId", requestId);
26+
var startTime = DateTimeOffset.UtcNow;
27+
28+
// Trace: Request received
29+
logger.LogInformation("[{RequestId}] Chat request received. Endpoint: /chat, HasSessionId: {HasSessionId}, DocumentIds: {DocumentCount}",
30+
requestId,
31+
!string.IsNullOrEmpty(request.ChatSessionId),
32+
request.DocumentIds?.Length ?? 0);
33+
34+
// Track request started
35+
telemetryHelper.TrackEvent("ChatRequestStarted", new Dictionary<string, string>
36+
{
37+
{ "requestId", requestId },
38+
{ "endpoint", "/chat" },
39+
{ "hasSessionId", (!string.IsNullOrEmpty(request.ChatSessionId)).ToString() },
40+
{ "documentCount", (request.DocumentIds?.Length ?? 0).ToString() }
41+
});
2642

2743
try
2844
{
29-
if (!validator.Validate(request).IsValid)
45+
// Trace: Starting validation
46+
logger.LogDebug("[{RequestId}] Validating chat request", requestId);
47+
48+
// Validate request
49+
var validationResult = validator.Validate(request);
50+
if (!validationResult.IsValid)
3051
{
52+
var errors = string.Join("; ", validationResult.Errors.Select(e => e.ErrorMessage));
53+
54+
// Trace: Validation failed
55+
logger.LogWarning("[{RequestId}] Chat request validation failed. Errors: {ValidationErrors}",
56+
requestId, errors);
57+
3158
telemetryHelper.TrackEvent("ChatRequestValidationFailed", new Dictionary<string, string>
3259
{
60+
{ "requestId", requestId },
3361
{ "endpoint", "/chat" },
34-
{ "requestId", requestId }
62+
{ "validationErrors", errors }
3563
});
3664
return Results.BadRequest();
3765
}
66+
67+
// Trace: Validation passed, processing request
68+
logger.LogInformation("[{RequestId}] Request validation passed. Calling chat host...", requestId);
3869

3970
var result = await chatHost.Chat(request);
71+
var duration = (DateTimeOffset.UtcNow - startTime).TotalSeconds;
4072

41-
// Track successful chat request
73+
// Trace: Request completed successfully
74+
logger.LogInformation("[{RequestId}] Chat request completed successfully. Duration: {Duration}s, ChatSessionId: {ChatSessionId}, Documents: {DocumentCount}, AnswerLength: {AnswerLength}",
75+
requestId,
76+
duration.ToString("F2"),
77+
result.ChatSessionId ?? "unknown",
78+
result.DocumentIds?.Length ?? 0,
79+
result.Answer?.Length ?? 0);
80+
81+
// Track successful chat request with metrics
4282
telemetryHelper.TrackEvent("ChatRequestSuccess", new Dictionary<string, string>
4383
{
4484
{ "requestId", requestId },
4585
{ "chatSessionId", result.ChatSessionId ?? "unknown" },
46-
{ "documentCount", result.DocumentIds?.Length.ToString() ?? "0" }
86+
{ "documentCount", result.DocumentIds?.Length.ToString() ?? "0" },
87+
{ "hasSuggestedQuestions", (result.SuggestingQuestions?.Length > 0).ToString() },
88+
{ "answerLength", result.Answer?.Length.ToString() ?? "0" },
89+
{ "duration", duration.ToString("F2") }
90+
}, new Dictionary<string, double>
91+
{
92+
{ "ResponseTimeSeconds", duration },
93+
{ "DocumentsReferenced", result.DocumentIds?.Length ?? 0 }
4794
});
4895

4996
// Set correlation ID for tracing
@@ -52,11 +99,100 @@ public static void AddAPIs(WebApplication app)
5299
telemetryHelper.SetActivityTag("chatSessionId", result.ChatSessionId);
53100
}
54101

102+
// Track performance metrics
103+
if (duration > 60)
104+
{
105+
// Trace: Slow response warning
106+
logger.LogWarning("[{RequestId}] SLOW RESPONSE DETECTED: Chat request took {Duration}s (threshold: 60s). DocumentCount: {DocumentCount}",
107+
requestId,
108+
duration.ToString("F2"),
109+
result.DocumentIds?.Length ?? 0);
110+
111+
telemetryHelper.TrackEvent("ChatRequestSlowResponse", new Dictionary<string, string>
112+
{
113+
{ "requestId", requestId },
114+
{ "duration", duration.ToString("F2") },
115+
{ "documentCount", result.DocumentIds?.Length.ToString() ?? "0" }
116+
});
117+
}
118+
else if (duration > 30)
119+
{
120+
// Trace: Performance warning for moderately slow requests
121+
logger.LogInformation("[{RequestId}] Moderate response time: {Duration}s",
122+
requestId, duration.ToString("F2"));
123+
}
124+
55125
return Results.Ok<ChatResponse>(result);
56126
}
127+
catch (TimeoutException ex)
128+
{
129+
var elapsedTime = (DateTimeOffset.UtcNow - startTime).TotalSeconds;
130+
131+
// Trace: Timeout with details
132+
logger.LogError(ex, "[{RequestId}] TIMEOUT: Chat request timed out after {ElapsedTime}s. Endpoint: /chat, Message: {ErrorMessage}",
133+
requestId,
134+
elapsedTime.ToString("F2"),
135+
ex.Message);
136+
137+
telemetryHelper.TrackEvent("ChatRequestTimeout", new Dictionary<string, string>
138+
{
139+
{ "requestId", requestId },
140+
{ "endpoint", "/chat" },
141+
{ "elapsedTime", elapsedTime.ToString("F2") },
142+
{ "errorMessage", ex.Message }
143+
});
144+
telemetryHelper.TrackException(ex, new Dictionary<string, string>
145+
{
146+
{ "requestId", requestId },
147+
{ "endpoint", "/chat" },
148+
{ "errorType", "TimeoutException" }
149+
});
150+
throw;
151+
}
152+
catch (ArgumentException ex)
153+
{
154+
// Trace: Invalid argument with parameter details
155+
logger.LogError(ex, "[{RequestId}] INVALID ARGUMENT: Chat request failed due to invalid parameter. Endpoint: /chat, Parameter: {ParamName}, Message: {ErrorMessage}",
156+
requestId,
157+
ex.ParamName ?? "unknown",
158+
ex.Message);
159+
160+
telemetryHelper.TrackEvent("ChatRequestInvalidArgument", new Dictionary<string, string>
161+
{
162+
{ "requestId", requestId },
163+
{ "endpoint", "/chat" },
164+
{ "paramName", ex.ParamName ?? "unknown" },
165+
{ "errorMessage", ex.Message }
166+
});
167+
telemetryHelper.TrackException(ex, new Dictionary<string, string>
168+
{
169+
{ "requestId", requestId },
170+
{ "endpoint", "/chat" },
171+
{ "errorType", "ArgumentException" }
172+
});
173+
throw;
174+
}
57175
catch (Exception ex)
58176
{
59-
logger.LogError(ex, "Error processing chat request. RequestId: {RequestId}", requestId);
177+
var elapsedTime = (DateTimeOffset.UtcNow - startTime).TotalSeconds;
178+
179+
// Trace: General error with full context
180+
logger.LogError(ex, "[{RequestId}] CHAT REQUEST FAILED: Unexpected error after {ElapsedTime}s. Endpoint: /chat, ErrorType: {ErrorType}, Message: {ErrorMessage}, StackTrace: {StackTrace}",
181+
requestId,
182+
elapsedTime.ToString("F2"),
183+
ex.GetType().Name,
184+
ex.Message,
185+
ex.StackTrace?.Substring(0, Math.Min(500, ex.StackTrace?.Length ?? 0)) ?? "N/A");
186+
187+
telemetryHelper.TrackEvent("ChatRequestFailed", new Dictionary<string, string>
188+
{
189+
{ "requestId", requestId },
190+
{ "endpoint", "/chat" },
191+
{ "errorType", ex.GetType().Name },
192+
{ "errorMessage", ex.Message },
193+
{ "elapsedTime", elapsedTime.ToString("F2") },
194+
{ "innerException", ex.InnerException?.Message ?? "none" }
195+
});
60196
telemetryHelper.TrackException(ex, new Dictionary<string, string>
61197
{
62198
{ "requestId", requestId },
@@ -82,23 +218,61 @@ public static void AddAPIs(WebApplication app)
82218
// Generate unique request ID for tracking
83219
var requestId = ctx.TraceIdentifier;
84220
telemetryHelper.SetActivityTag("requestId", requestId);
221+
var startTime = DateTimeOffset.UtcNow;
222+
223+
// Trace: Async request received
224+
logger.LogInformation("[{RequestId}] Chat ASYNC request received. Endpoint: /chatAsync, HasSessionId: {HasSessionId}, DocumentIds: {DocumentCount}",
225+
requestId,
226+
!string.IsNullOrEmpty(request.ChatSessionId),
227+
request.DocumentIds?.Length ?? 0);
228+
229+
// Track async request started
230+
telemetryHelper.TrackEvent("ChatAsyncRequestStarted", new Dictionary<string, string>
231+
{
232+
{ "requestId", requestId },
233+
{ "endpoint", "/chatAsync" },
234+
{ "hasSessionId", (!string.IsNullOrEmpty(request.ChatSessionId)).ToString() },
235+
{ "documentCount", (request.DocumentIds?.Length ?? 0).ToString() }
236+
});
85237

86238
try
87239
{
88-
if (!validator.Validate(request).IsValid)
240+
// Trace: Starting validation
241+
logger.LogDebug("[{RequestId}] Validating chat async request", requestId);
242+
243+
var validationResult = validator.Validate(request);
244+
if (!validationResult.IsValid)
89245
{
246+
var errors = string.Join("; ", validationResult.Errors.Select(e => e.ErrorMessage));
247+
248+
// Trace: Validation failed
249+
logger.LogWarning("[{RequestId}] Chat async request validation failed. Errors: {ValidationErrors}",
250+
requestId, errors);
251+
90252
telemetryHelper.TrackEvent("ChatAsyncRequestValidationFailed", new Dictionary<string, string>
91253
{
254+
{ "requestId", requestId },
92255
{ "endpoint", "/chatAsync" },
93-
{ "requestId", requestId }
256+
{ "validationErrors", errors }
94257
});
95258
return Results.BadRequest();
96259
}
97260

261+
// Trace: Validation passed, preparing streaming response
262+
logger.LogInformation("[{RequestId}] Request validation passed. Preparing streaming response...", requestId);
263+
98264
ctx.Response.ContentType = "text/plain";
99265

100266
//Make a response as a stream
101267
var result = chatHost.ChatAsync(request).Result;
268+
var duration = (DateTimeOffset.UtcNow - startTime).TotalSeconds;
269+
270+
// Trace: Response metadata ready
271+
logger.LogInformation("[{RequestId}] Chat async response ready. Duration: {Duration}s, ChatSessionId: {ChatSessionId}, Documents: {DocumentCount}",
272+
requestId,
273+
duration.ToString("F2"),
274+
result.ChatSessionId ?? "unknown",
275+
result.DocumentIds?.Length ?? 0);
102276

103277
//Create a dynamic object to store the response
104278
var response = new
@@ -111,12 +285,19 @@ public static void AddAPIs(WebApplication app)
111285
//Add the response to the header
112286
ctx.Response.Headers.Add("RESPONSE", JsonSerializer.Serialize(response));
113287

114-
// Track successful chat async request
288+
// Track successful chat async request with metrics
115289
telemetryHelper.TrackEvent("ChatAsyncRequestSuccess", new Dictionary<string, string>
116290
{
117291
{ "requestId", requestId },
118292
{ "chatSessionId", result.ChatSessionId ?? "unknown" },
119-
{ "documentCount", result.DocumentIds?.Length.ToString() ?? "0" }
293+
{ "documentCount", result.DocumentIds?.Length.ToString() ?? "0" },
294+
{ "hasSuggestedQuestions", (result.SuggestingQuestions?.Length > 0).ToString() },
295+
{ "streamingResponse", "true" },
296+
{ "duration", duration.ToString("F2") }
297+
}, new Dictionary<string, double>
298+
{
299+
{ "ResponseTimeSeconds", duration },
300+
{ "DocumentsReferenced", result.DocumentIds?.Length ?? 0 }
120301
});
121302

122303
// Set correlation ID for tracing
@@ -125,17 +306,70 @@ public static void AddAPIs(WebApplication app)
125306
telemetryHelper.SetActivityTag("chatSessionId", result.ChatSessionId);
126307
}
127308

309+
// Trace: Beginning streaming
310+
logger.LogDebug("[{RequestId}] Starting to stream response words...", requestId);
311+
128312
// Stream the response
313+
var wordCount = 0;
129314
await foreach (var word in result.AnswerWords)
130315
{
131316
await ctx.Response.WriteAsync(word);
132317
await ctx.Response.WriteAsync(" ");
318+
wordCount++;
133319
}
320+
321+
// Trace: Streaming completed
322+
logger.LogInformation("[{RequestId}] Streaming completed. Total words streamed: {WordCount}",
323+
requestId, wordCount);
324+
134325
return Results.Ok();
135326
}
327+
catch (TimeoutException ex)
328+
{
329+
var elapsedTime = (DateTimeOffset.UtcNow - startTime).TotalSeconds;
330+
331+
// Trace: Timeout with details
332+
logger.LogError(ex, "[{RequestId}] TIMEOUT: Chat async request timed out after {ElapsedTime}s. Endpoint: /chatAsync, Message: {ErrorMessage}",
333+
requestId,
334+
elapsedTime.ToString("F2"),
335+
ex.Message);
336+
337+
telemetryHelper.TrackEvent("ChatAsyncRequestTimeout", new Dictionary<string, string>
338+
{
339+
{ "requestId", requestId },
340+
{ "endpoint", "/chatAsync" },
341+
{ "elapsedTime", elapsedTime.ToString("F2") },
342+
{ "errorMessage", ex.Message }
343+
});
344+
telemetryHelper.TrackException(ex, new Dictionary<string, string>
345+
{
346+
{ "requestId", requestId },
347+
{ "endpoint", "/chatAsync" },
348+
{ "errorType", "TimeoutException" }
349+
});
350+
throw;
351+
}
136352
catch (Exception ex)
137353
{
138-
logger.LogError(ex, "Error processing chat async request. RequestId: {RequestId}", requestId);
354+
var elapsedTime = (DateTimeOffset.UtcNow - startTime).TotalSeconds;
355+
356+
// Trace: General error with full context
357+
logger.LogError(ex, "[{RequestId}] CHAT ASYNC REQUEST FAILED: Unexpected error after {ElapsedTime}s. Endpoint: /chatAsync, ErrorType: {ErrorType}, Message: {ErrorMessage}, StackTrace: {StackTrace}",
358+
requestId,
359+
elapsedTime.ToString("F2"),
360+
ex.GetType().Name,
361+
ex.Message,
362+
ex.StackTrace?.Substring(0, Math.Min(500, ex.StackTrace?.Length ?? 0)) ?? "N/A");
363+
364+
telemetryHelper.TrackEvent("ChatAsyncRequestFailed", new Dictionary<string, string>
365+
{
366+
{ "requestId", requestId },
367+
{ "endpoint", "/chatAsync" },
368+
{ "errorType", ex.GetType().Name },
369+
{ "errorMessage", ex.Message },
370+
{ "elapsedTime", elapsedTime.ToString("F2") },
371+
{ "innerException", ex.InnerException?.Message ?? "none" }
372+
});
139373
telemetryHelper.TrackException(ex, new Dictionary<string, string>
140374
{
141375
{ "requestId", requestId },

0 commit comments

Comments
 (0)