Conversation
The middleware was creating the transformed response (with queryID, payloadPath, schema, etc.) but only returning it in the second return value. When the handler was wrapped for the SDK, this value was discarded with `_`, so the client never received the metadata. Now the middleware creates a new CallToolResult with the transformed response in the Content field, which is what gets sent to the client via the MCP protocol. Co-authored-by: lpcox <15877973+lpcox@users.noreply.github.com>
Co-authored-by: lpcox <15877973+lpcox@users.noreply.github.com>
|
@copilot make sure that there is extensive logging around large payloads and sharing them through the file system |
Enhanced integration tests to verify that the transformed response (with queryID, payloadPath, schema, etc.) is properly included in the CallToolResult.Content field, not just in the internal data return value. Co-authored-by: lpcox <15877973+lpcox@users.noreply.github.com>
…ions Enhanced middleware logging to provide detailed visibility into: - Payload directory creation and verification - File write operations with size and permissions - Payload size in multiple units (bytes, KB, MB) - Metadata generation and client response details - Path information for accessing payloads inside containers - Error conditions with full context Added both debug logs (logMiddleware.Printf) and operational logs (logger.LogInfo/LogDebug/LogWarn/LogError) to ensure comprehensive tracking in both console output and log files. Co-authored-by: lpcox <15877973+lpcox@users.noreply.github.com>
Added extensive logging in commit 27dbad2. The middleware now logs: Payload Storage:
Processing Flow:
Client Response:
All logs use both debug console output ( |
There was a problem hiding this comment.
Pull request overview
Fixes the large payload middleware so MCP clients actually receive payload metadata by populating CallToolResult.Content (the only part of the tool result sent over the protocol), and updates tests to validate this behavior.
Changes:
- Populate
sdk.CallToolResult.Contentwith JSON-encoded metadata (queryID,payloadPath,schema,preview,originalSize,truncated) asTextContent. - Add extensive operational/debug logging around payload persistence and metadata generation.
- Update unit + integration tests to assert metadata is present in
result.Content(and still returned via the internaldatavalue).
Reviewed changes
Copilot reviewed 3 out of 3 changed files in this pull request and generated 6 comments.
| File | Description |
|---|---|
| internal/middleware/jqschema.go | Returns rewritten metadata via CallToolResult.Content and adds detailed payload lifecycle logging. |
| internal/middleware/jqschema_test.go | Updates unit tests to parse/validate metadata from result.Content in addition to data. |
| internal/middleware/jqschema_integration_test.go | Updates integration tests to validate end-to-end metadata delivery through result.Content. |
💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.
| logMiddleware.Printf("Rewritten response: tool=%s, queryID=%s, sessionID=%s, originalSize=%d, truncated=%v", | ||
| toolName, queryID, sessionID, len(payloadJSON), len(payloadStr) > 500) | ||
| toolName, queryID, sessionID, len(payloadJSON), truncated) | ||
| logger.LogInfo("payload", "Created metadata response for client: tool=%s, queryID=%s, session=%s, payloadPath=%s, originalSize=%d bytes, truncated=%v", | ||
| toolName, queryID, sessionID, filePath, len(payloadJSON), truncated) |
There was a problem hiding this comment.
If savePayload fails, filePath will be empty but the middleware still builds/returns client metadata and logs a payloadPath. That can mislead clients into trying to read a non-existent file. Consider only returning/advertising payloadPath when saveErr == nil (or explicitly include storage failure info in the metadata).
See below for a potential fix:
"preview": preview,
"schema": schemaJSON,
"originalSize": len(payloadJSON),
"truncated": truncated,
}
// Only advertise payloadPath when we actually have a stored payload
if filePath != "" {
rewrittenResponse["payloadPath"] = filePath
}
logMiddleware.Printf("Rewritten response: tool=%s, queryID=%s, sessionID=%s, originalSize=%d, truncated=%v",
toolName, queryID, sessionID, len(payloadJSON), truncated)
if filePath != "" {
logger.LogInfo("payload", "Created metadata response for client: tool=%s, queryID=%s, session=%s, payloadPath=%s, originalSize=%d bytes, truncated=%v",
toolName, queryID, sessionID, filePath, len(payloadJSON), truncated)
} else {
logger.LogInfo("payload", "Created metadata response for client without payloadPath: tool=%s, queryID=%s, session=%s, originalSize=%d bytes, truncated=%v",
toolName, queryID, sessionID, len(payloadJSON), truncated)
}
| logger.LogInfo("payload", "Writing large payload to filesystem: path=%s, size=%d bytes (%.2f KB, %.2f MB)", | ||
| filePath, payloadSize, float64(payloadSize)/1024, float64(payloadSize)/(1024*1024)) | ||
|
|
||
| if err := os.WriteFile(filePath, payload, 0600); err != nil { | ||
| logger.LogError("payload", "Failed to write payload file: path=%s, size=%d bytes, error=%v", |
There was a problem hiding this comment.
These LogInfo messages are emitted for every wrapped tool call (the middleware saves all payloads), and the underlying file logger fsyncs on each log write. This combination can significantly increase I/O and latency in production. Consider downgrading most of these messages to debug (or sampling), and avoid wording like "large payload" unless there is an actual size threshold.
| // Verify file was written correctly | ||
| if stat, err := os.Stat(filePath); err != nil { | ||
| logger.LogWarn("payload", "Could not verify payload file after write: path=%s, error=%v", filePath, err) | ||
| } else { | ||
| logger.LogDebug("payload", "Payload file verified: path=%s, size=%d bytes, mode=%s", | ||
| filePath, stat.Size(), stat.Mode()) | ||
| } | ||
|
|
There was a problem hiding this comment.
The post-write verification does an extra os.Stat() on the hot path. Combined with always-on payload writes, this adds filesystem overhead without affecting correctness. Consider guarding this behind debug logging (or removing it) to reduce unnecessary I/O.
| // Verify file was written correctly | |
| if stat, err := os.Stat(filePath); err != nil { | |
| logger.LogWarn("payload", "Could not verify payload file after write: path=%s, error=%v", filePath, err) | |
| } else { | |
| logger.LogDebug("payload", "Payload file verified: path=%s, size=%d bytes, mode=%s", | |
| filePath, stat.Size(), stat.Mode()) | |
| } |
| logger.LogInfo("payload", "Client can access full payload at: %s (inside container: /workspace/mcp-payloads/%s/%s/payload.json)", | ||
| filePath, sessionID, queryID) |
There was a problem hiding this comment.
This log line hardcodes an agent/container path (/workspace/mcp-payloads/...) that depends on workflow-specific mounts and may be incorrect in most deployments. Consider removing the hardcoded path, or deriving/logging it from configuration so operational logs don’t mislead users about where the payload is accessible.
| assert.Contains(t, contentMap, "truncated", "Content should contain truncated") | ||
|
|
||
| // Verify queryID format in Content | ||
| queryIDFromContent := contentMap["queryID"].(string) |
There was a problem hiding this comment.
These tests use direct type assertions on values pulled from a map resulting from json.Unmarshal (e.g., contentMap["queryID"].(string)). If the key is missing or the type changes, the test will panic and produce a less actionable failure. Prefer require.Contains/require.True checks (or require.IsType) before asserting types/values.
| queryIDFromContent := contentMap["queryID"].(string) | |
| queryIDValue, ok := contentMap["queryID"] | |
| require.True(t, ok, "Content queryID should be present") | |
| queryIDFromContent, ok := queryIDValue.(string) | |
| require.True(t, ok, "Content queryID should be a string") |
| assert.True(t, contentMap["truncated"].(bool), "Should indicate truncation in Content") | ||
| preview := contentMap["preview"].(string) | ||
| assert.LessOrEqual(t, len(preview), 503, "Preview should be truncated to ~500 chars + '...'") | ||
| assert.True(t, strings.HasSuffix(preview, "..."), "Preview should end with '...'") | ||
|
|
||
| // Also verify in data return value | ||
| dataMap, ok := data.(map[string]interface{}) | ||
| require.True(t, ok, "Data should be a map") | ||
| assert.True(t, dataMap["truncated"].(bool), "Should indicate truncation in data") |
There was a problem hiding this comment.
This test directly type-asserts fields from contentMap (e.g., contentMap["truncated"].(bool), contentMap["preview"].(string)). If the JSON shape changes, the test will panic instead of failing with a clear assertion message. Consider asserting the keys exist and types are expected before using them.
| assert.True(t, contentMap["truncated"].(bool), "Should indicate truncation in Content") | |
| preview := contentMap["preview"].(string) | |
| assert.LessOrEqual(t, len(preview), 503, "Preview should be truncated to ~500 chars + '...'") | |
| assert.True(t, strings.HasSuffix(preview, "..."), "Preview should end with '...'") | |
| // Also verify in data return value | |
| dataMap, ok := data.(map[string]interface{}) | |
| require.True(t, ok, "Data should be a map") | |
| assert.True(t, dataMap["truncated"].(bool), "Should indicate truncation in data") | |
| truncatedVal, ok := contentMap["truncated"] | |
| require.True(t, ok, "Content JSON should contain 'truncated' field") | |
| truncated, ok := truncatedVal.(bool) | |
| require.True(t, ok, "'truncated' field in Content JSON should be a bool") | |
| assert.True(t, truncated, "Should indicate truncation in Content") | |
| previewVal, ok := contentMap["preview"] | |
| require.True(t, ok, "Content JSON should contain 'preview' field") | |
| preview, ok := previewVal.(string) | |
| require.True(t, ok, "'preview' field in Content JSON should be a string") | |
| assert.LessOrEqual(t, len(preview), 503, "Preview should be truncated to ~500 chars + '...'") | |
| assert.True(t, strings.HasSuffix(preview, "..."), "Preview should end with '...'") | |
| // Also verify in data return value | |
| dataMap, ok := data.(map[string]interface{}) | |
| require.True(t, ok, "Data should be a map") | |
| dataTruncatedVal, ok := dataMap["truncated"] | |
| require.True(t, ok, "Data JSON should contain 'truncated' field") | |
| dataTruncated, ok := dataTruncatedVal.(bool) | |
| require.True(t, ok, "'truncated' field in data JSON should be a bool") | |
| assert.True(t, dataTruncated, "Should indicate truncation in data") |
Problem
Large payload middleware saves payloads to disk and generates metadata (queryID, payloadPath, schema) but clients receive full payloads without metadata. Test run 21762627709 showed 672KB response passed through unchanged.
Root Cause
Middleware returned transformed response in second return value, which gets discarded when wrapping for MCP SDK:
MCP protocol sends only
CallToolResult.Contentto clients. Second return value is internal-only.Changes
Modified
internal/middleware/jqschema.go:CallToolResultwith transformed response inContentfieldTextContentEnhanced Logging:
logMiddleware.Printf) and operational file logging (logger.LogInfo/LogDebug/LogWarn/LogError)Updated tests:
Contentfield contains transformed response with metadataResult
Clients now receive:
{ "queryID": "abc123...", "payloadPath": "/tmp/jq-payloads/session/query/payload.json", "preview": "first 500 chars...", "schema": {...}, "originalSize": 672508, "truncated": true }The enhanced logging provides comprehensive visibility into the entire payload lifecycle, making it easier to diagnose storage issues and track filesystem operations in both development and production environments.
Original prompt
💡 You can make Copilot smarter by setting up custom instructions, customizing its development environment and configuring Model Context Protocol (MCP) servers. Learn more Copilot coding agent tips in the docs.