Skip to content

Commit 33b7e8f

Browse files
stephentoubCopilot
stephentoub
and
Copilot
authored
Add SDK tracing diagnostics (#1217)
* Add SDK tracing diagnostics Add native logging and timing diagnostics across the .NET, Python, and Rust SDKs for client startup, JSON-RPC calls, session lifecycle operations, event dispatch, and callback handling. Align diagnostics so each SDK reports useful startup breadcrumbs, CLI output, structured timing fields, and failure paths while staying idiomatic for ILogger, Python logging, and tracing. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Fix SDK tracing log analyzer warnings Use source-generated ILogger methods for the new C# startup intent logs so analyzer CA1873 does not flag argument evaluation. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Centralize SDK timing helpers Move repeated timing helper logic into shared helpers for .NET, Python, and Rust so elapsed calculation and logging behavior stay consistent across modules. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Address Rust tracing review feedback Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Align SDK tracing log levels Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --------- Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
1 parent 5600f41 commit 33b7e8f

12 files changed

Lines changed: 1489 additions & 207 deletions

File tree

‎dotnet/src/Client.cs‎

Lines changed: 134 additions & 9 deletions
Large diffs are not rendered by default.

‎dotnet/src/JsonRpc.cs‎

Lines changed: 39 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -77,6 +77,7 @@ public void StartListening()
7777
/// </summary>
7878
public async Task<T> InvokeAsync<T>(string method, object?[]? args, CancellationToken cancellationToken)
7979
{
80+
var timingTimestamp = Stopwatch.GetTimestamp();
8081
var id = Interlocked.Increment(ref _nextId);
8182
var pending = new PendingRequest();
8283
_pendingRequests[id] = pending;
@@ -111,10 +112,23 @@ await SendMessageAsync(new JsonRpcRequest
111112

112113
if (responseElement.ValueKind == JsonValueKind.Null || responseElement.ValueKind == JsonValueKind.Undefined)
113114
{
115+
LogInvokeTiming(LogLevel.Debug, null, method, id, "Succeeded", timingTimestamp);
114116
return default!;
115117
}
116118

117-
return (T)responseElement.Deserialize(_serializerOptions.GetTypeInfo(typeof(T)))!;
119+
var result = (T)responseElement.Deserialize(_serializerOptions.GetTypeInfo(typeof(T)))!;
120+
LogInvokeTiming(LogLevel.Debug, null, method, id, "Succeeded", timingTimestamp);
121+
return result;
122+
}
123+
catch (OperationCanceledException ex)
124+
{
125+
LogInvokeTiming(LogLevel.Debug, ex, method, id, "Canceled", timingTimestamp);
126+
throw;
127+
}
128+
catch (Exception ex)
129+
{
130+
LogInvokeTiming(LogLevel.Warning, ex, method, id, "Failed", timingTimestamp);
131+
throw;
118132
}
119133
finally
120134
{
@@ -123,6 +137,30 @@ await SendMessageAsync(new JsonRpcRequest
123137
}
124138
}
125139

140+
private void LogInvokeTiming(
141+
LogLevel level,
142+
Exception? exception,
143+
string method,
144+
long requestId,
145+
string status,
146+
long startTimestamp)
147+
{
148+
if (!_logger.IsEnabled(level))
149+
{
150+
return;
151+
}
152+
153+
var elapsed = Stopwatch.GetElapsedTime(startTimestamp);
154+
_logger.Log(
155+
level,
156+
exception,
157+
"JsonRpc.InvokeAsync JSON-RPC request finished. Elapsed={Elapsed}, Method={Method}, RequestId={RequestId}, Status={Status}",
158+
elapsed,
159+
method,
160+
requestId,
161+
status);
162+
}
163+
126164
/// <summary>
127165
/// Registers a method handler that receives positional parameters.
128166
/// If singleObjectParam is false (the default), parameter names and types are inferred from the delegate's signature.

‎dotnet/src/LoggingHelpers.cs‎

Lines changed: 108 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,108 @@
1+
/*---------------------------------------------------------------------------------------------
2+
* Copyright (c) Microsoft Corporation. All rights reserved.
3+
*--------------------------------------------------------------------------------------------*/
4+
5+
using Microsoft.Extensions.Logging;
6+
using System.Diagnostics;
7+
8+
namespace GitHub.Copilot.SDK;
9+
10+
internal static class LoggingHelpers
11+
{
12+
internal static void LogTiming(
13+
ILogger logger,
14+
LogLevel level,
15+
Exception? exception,
16+
string message,
17+
long startTimestamp)
18+
{
19+
if (!logger.IsEnabled(level))
20+
{
21+
return;
22+
}
23+
24+
LogTimingCore(logger, level, exception, message, Stopwatch.GetElapsedTime(startTimestamp));
25+
}
26+
27+
internal static void LogTiming<T1>(
28+
ILogger logger,
29+
LogLevel level,
30+
Exception? exception,
31+
string message,
32+
long startTimestamp,
33+
T1 arg1)
34+
{
35+
if (!logger.IsEnabled(level))
36+
{
37+
return;
38+
}
39+
40+
LogTimingCore(logger, level, exception, message, Stopwatch.GetElapsedTime(startTimestamp), arg1);
41+
}
42+
43+
internal static void LogTiming<T1, T2>(
44+
ILogger logger,
45+
LogLevel level,
46+
Exception? exception,
47+
string message,
48+
long startTimestamp,
49+
T1 arg1,
50+
T2 arg2)
51+
{
52+
if (!logger.IsEnabled(level))
53+
{
54+
return;
55+
}
56+
57+
LogTimingCore(logger, level, exception, message, Stopwatch.GetElapsedTime(startTimestamp), arg1, arg2);
58+
}
59+
60+
internal static void LogTiming<T1, T2, T3>(
61+
ILogger logger,
62+
LogLevel level,
63+
Exception? exception,
64+
string message,
65+
long startTimestamp,
66+
T1 arg1,
67+
T2 arg2,
68+
T3 arg3)
69+
{
70+
if (!logger.IsEnabled(level))
71+
{
72+
return;
73+
}
74+
75+
LogTimingCore(logger, level, exception, message, Stopwatch.GetElapsedTime(startTimestamp), arg1, arg2, arg3);
76+
}
77+
78+
internal static void LogTiming<T1, T2, T3, T4>(
79+
ILogger logger,
80+
LogLevel level,
81+
Exception? exception,
82+
string message,
83+
long startTimestamp,
84+
T1 arg1,
85+
T2 arg2,
86+
T3 arg3,
87+
T4 arg4)
88+
{
89+
if (!logger.IsEnabled(level))
90+
{
91+
return;
92+
}
93+
94+
LogTimingCore(logger, level, exception, message, Stopwatch.GetElapsedTime(startTimestamp), arg1, arg2, arg3, arg4);
95+
}
96+
97+
private static void LogTimingCore(
98+
ILogger logger,
99+
LogLevel level,
100+
Exception? exception,
101+
string message,
102+
params object?[] args)
103+
{
104+
#pragma warning disable CA2254 // Timing call sites pass static templates through this helper.
105+
logger.Log(level, exception, message, args);
106+
#pragma warning restore CA2254
107+
}
108+
}

0 commit comments

Comments
 (0)