Skip to content

Enhance HTTP and MCP session logging #608

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 5 commits into
base: main
Choose a base branch
from
+10 −2
Open

Enhance HTTP and MCP session logging #608

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
a15163d
add debug log for McpSession
theojiang25 Jul 10, 2025
64761d0
add request header logging at trace level
theojiang25 Jul 10, 2025
c5d7009
Revert "add request header logging at trace level"
theojiang25 Jul 10, 2025
adbec9a
remove session connected log and move to trace level
theojiang25 Jul 10, 2025
21ab803
Merge branch 'main' into theojiang/logging
theojiang25 Jul 10, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
46 changes: 45 additions & 1 deletion src/ModelContextProtocol.AspNetCore/StreamableHttpHandler.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,7 @@

namespace ModelContextProtocol.AspNetCore;

internal sealed class StreamableHttpHandler(
internal sealed partial class StreamableHttpHandler(
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't see why this was made into a partial class.

Copy link
Author

@theojiang25 theojiang25 Jul 10, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Made it a partial class because I wanted to use the LoggerMessage generation. Removed the Http header logs per comment.

IOptions<McpServerOptions> mcpServerOptionsSnapshot,
IOptionsFactory<McpServerOptions> mcpServerOptionsFactory,
IOptions<HttpServerTransportOptions> httpServerTransportOptions,
Expand All @@ -28,6 +28,20 @@ internal sealed class StreamableHttpHandler(
{
private const string McpSessionIdHeaderName = "Mcp-Session-Id";
private static readonly JsonTypeInfo<JsonRpcError> s_errorTypeInfo = GetRequiredJsonTypeInfo<JsonRpcError>();

private readonly ILogger _logger = loggerFactory.CreateLogger<StreamableHttpHandler>();

// Headers that are safe and relevant to log for MCP over HTTP
private static readonly HashSet<string> SafeHeadersToLog = new(StringComparer.OrdinalIgnoreCase)
{
"Accept",
"Content-Type",
"Content-Length",
"User-Agent",
McpSessionIdHeaderName,
"X-Request-ID",
"X-Correlation-ID"
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure if it should be the responsibility of the MCP SDK to log HTTP headers. Have you considered using ASP.NET Core's HTTP logging middleware instead? https://learn.microsoft.com/en-us/aspnet/core/fundamentals/http-logging/?view=aspnetcore-9.0#enable-http-logging

This allows each application developer to configure exactly what set of request and response headers to log, redact certain headers, log request and response bodies, and a lot more.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the pointer, that makes a lot of sense. Removed this change.

};

public ConcurrentDictionary<string, HttpMcpSession<StreamableHttpServerTransport>> Sessions { get; } = new(StringComparer.Ordinal);

Expand All @@ -37,6 +51,9 @@ internal sealed class StreamableHttpHandler(

public async Task HandlePostRequestAsync(HttpContext context)
{
// Log request headers for debugging
LogHttpRequestHeadersIfEnabled(context);

// The Streamable HTTP spec mandates the client MUST accept both application/json and text/event-stream.
// ASP.NET Core Minimal APIs mostly try to stay out of the business of response content negotiation,
// so we have to do this manually. The spec doesn't mandate that servers MUST reject these requests,
Expand Down Expand Up @@ -83,6 +100,9 @@ await WriteJsonRpcErrorAsync(context,

public async Task HandleGetRequestAsync(HttpContext context)
{
// Log request headers for debugging
LogHttpRequestHeadersIfEnabled(context);

if (!context.Request.GetTypedHeaders().Accept.Any(MatchesTextEventStreamMediaType))
{
await WriteJsonRpcErrorAsync(context,
Expand Down Expand Up @@ -118,6 +138,9 @@ await WriteJsonRpcErrorAsync(context,

public async Task HandleDeleteRequestAsync(HttpContext context)
{
// Log request headers for debugging
LogHttpRequestHeadersIfEnabled(context);

var sessionId = context.Request.Headers[McpSessionIdHeaderName].ToString();
if (Sessions.TryRemove(sessionId, out var session))
{
Expand Down Expand Up @@ -336,6 +359,27 @@ private static bool MatchesApplicationJsonMediaType(MediaTypeHeaderValue acceptH
private static bool MatchesTextEventStreamMediaType(MediaTypeHeaderValue acceptHeaderValue)
=> acceptHeaderValue.MatchesMediaType("text/event-stream");

private void LogHttpRequestHeadersIfEnabled(HttpContext context)
{
if (_logger.IsEnabled(LogLevel.Trace))
{
var safeHeaders = new Dictionary<string, string>();

foreach (var header in context.Request.Headers)
{
if (SafeHeadersToLog.Contains(header.Key))
{
safeHeaders[header.Key] = header.Value.ToString();
}
}

LogHttpRequestHeaders(context.Request.Method, context.Request.Path, safeHeaders);
}
}

[LoggerMessage(Level = LogLevel.Trace, Message = "HTTP {Method} {Path} - Headers: {Headers}")]
private partial void LogHttpRequestHeaders(string method, string path, Dictionary<string, string> headers);

private sealed class HttpDuplexPipe(HttpContext context) : IDuplexPipe
{
public PipeReader Input => context.Request.BodyReader;
Expand Down
16 changes: 14 additions & 2 deletions src/ModelContextProtocol.Core/McpSession.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -95,6 +95,7 @@ public McpSession(
_requestHandlers = requestHandlers;
_notificationHandlers = notificationHandlers;
_logger = logger ?? NullLogger.Instance;
LogSessionCreated(EndpointName, _sessionId, _transportKind);
}

/// <summary>
Expand All @@ -108,6 +109,7 @@ public McpSession(
/// </summary>
public async Task ProcessMessagesAsync(CancellationToken cancellationToken)
{
LogSessionConnected(EndpointName, _sessionId, _transportKind);
try
{
await foreach (var message in _transport.MessageReader.ReadAllAsync(cancellationToken).ConfigureAwait(false))
Expand Down Expand Up @@ -609,9 +611,9 @@ private static void AddExceptionTags(ref TagList tags, Activity? activity, Excep
e = ae.InnerException;
}

int? intErrorCode =
int? intErrorCode =
(int?)((e as McpException)?.ErrorCode) is int errorCode ? errorCode :
e is JsonException ? (int)McpErrorCode.ParseError :
e is JsonException ? (int)McpErrorCode.ParseError :
null;

string? errorType = intErrorCode?.ToString() ?? e.GetType().FullName;
Expand Down Expand Up @@ -692,6 +694,7 @@ public void Dispose()
}

_pendingRequests.Clear();
LogSessionDisposed(EndpointName, _sessionId, _transportKind);
}

#if !NET
Expand Down Expand Up @@ -774,4 +777,13 @@ private static TimeSpan GetElapsed(long startingTimestamp) =>

[LoggerMessage(Level = LogLevel.Trace, Message = "{EndpointName} sending message. Message: '{Message}'.")]
private partial void LogSendingMessageSensitive(string endpointName, string message);

[LoggerMessage(Level = LogLevel.Debug, Message = "{EndpointName} session {SessionId} created with transport {TransportKind}")]
private partial void LogSessionCreated(string endpointName, string sessionId, string transportKind);
Copy link
Contributor

@halter73 halter73 Jul 10, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we make these trace level logs? The Streamable HTTP transport creates one of these per-request in Stateless mode, so this could get pretty noisy. I also don't think we need both LogSessionCreated and LogSessionConnected. Created and Disposed should be sufficient. "Connected" doesn't make much sense on the server side anyway.

Out of curiosity, what made you think that these events in particular were interesting? I wonder if moving these logs up a level to McpClient and McpServer would allow us to provide more informative log messages.

Copy link
Author

@theojiang25 theojiang25 Jul 10, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree that this could be very noisy, moved it to TRACE level.

Out of curiosity, what made you think that these events in particular were interesting? I wonder if moving these logs up a level to McpClient and McpServer would allow us to provide more informative log messages.

We had encountered issues related to session (session ID not found IIRC). And it's very hard to debug without any logs related to session lifecycle.
I looked into McpServer and McpEndpoint where getting session and creating new sessions are involved, I'm wondering if there's any extra information we can get out of it.


[LoggerMessage(Level = LogLevel.Debug, Message = "{EndpointName} session {SessionId} connected and processing messages with transport {TransportKind}")]
private partial void LogSessionConnected(string endpointName, string sessionId, string transportKind);

[LoggerMessage(Level = LogLevel.Debug, Message = "{EndpointName} session {SessionId} disposed with transport {TransportKind}")]
private partial void LogSessionDisposed(string endpointName, string sessionId, string transportKind);
}