From d3aeb7051dd0d3035f35c5c21ac94fe52313cda2 Mon Sep 17 00:00:00 2001 From: Eric Hare Date: Thu, 5 Nov 2026 11:00:00 -0800 Subject: [PATCH] fix: keep MCP payloads and credentials out of logs --- CONFIGURATION.md | 34 ++ .../jsonapi/api/request/RequestContext.java | 16 +- .../api/v1/mcp/GeneralCommandTools.java | 10 +- .../api/v1/mcp/KeyspaceCommandTools.java | 33 +- .../mcp/McpEndpointConfigSourceFactory.java | 51 +++ .../jsonapi/api/v1/mcp/McpLoggingFilter.java | 103 ++++++ .../api/v1/mcp/McpRequestContextProvider.java | 42 +++ .../jsonapi/api/v1/mcp/McpRequestLogging.java | 79 +++++ .../sgv2/jsonapi/api/v1/mcp/McpResource.java | 145 +++++---- .../service/cqldriver/CqlSessionFactory.java | 60 ++-- .../sgv2/jsonapi/util/DynamicTTLCache.java | 13 +- .../io.smallrye.config.ConfigSourceFactory | 1 + ...oprofile.context.spi.ThreadContextProvider | 1 + src/main/resources/application.yaml | 12 +- .../api/v1/mcp/McpCustomPathLoggingTest.java | 22 ++ .../api/v1/mcp/McpDiagnosticLoggingTest.java | 24 ++ .../McpEndpointConfigSourceFactoryTest.java | 69 ++++ .../api/v1/mcp/McpLoggingFilterTest.java | 146 +++++++++ .../api/v1/mcp/McpLoggingIntegrationTest.java | 94 ++++++ .../jsonapi/api/v1/mcp/McpLoggingTest.java | 304 ++++++++++++++++++ .../v1/mcp/McpRequestContextProviderTest.java | 162 ++++++++++ .../jsonapi/api/v1/mcp/McpResourceTest.java | 39 ++- .../api/v1/mcp/McpSetupErrorsTest.java | 48 ++- 23 files changed, 1366 insertions(+), 142 deletions(-) create mode 100644 src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpEndpointConfigSourceFactory.java create mode 100644 src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingFilter.java create mode 100644 src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpRequestContextProvider.java create mode 100644 src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpRequestLogging.java create mode 100644 src/main/resources/META-INF/services/io.smallrye.config.ConfigSourceFactory create mode 100644 src/main/resources/META-INF/services/org.eclipse.microprofile.context.spi.ThreadContextProvider create mode 100644 src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpCustomPathLoggingTest.java create mode 100644 src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpDiagnosticLoggingTest.java create mode 100644 src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpEndpointConfigSourceFactoryTest.java create mode 100644 src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingFilterTest.java create mode 100644 src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingIntegrationTest.java create mode 100644 src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingTest.java create mode 100644 src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpRequestContextProviderTest.java diff --git a/CONFIGURATION.md b/CONFIGURATION.md index b622e15f60..257ace4d34 100644 --- a/CONFIGURATION.md +++ b/CONFIGURATION.md @@ -75,6 +75,40 @@ Other Quarkus properties that are specifically relevant for the service: | `stargate.jsonapi.logging.only-results-with-errors` | `boolean` | `true` | Setting it to `true` prints the command level info only for the commands where the command result has errors. | | `stargate.jsonapi.logging.enabled-tenants` | `string` | `ALL` | Comma separated list of tenants for which command level logging should be enabled. Default is a special keyword called `ALL` which prints this log for all tenants | +## MCP logging + +Normal MCP logs contain generated request IDs, fixed protocol/command categories, HTTP status, +tool error flags, logger names and exception class names. They exclude document/query contents, +request/response bodies, client-supplied RPC IDs, credential headers, exception messages and +user-controlled logging context. MCP access URLs are excluded from the standard access log and +replaced with request summaries. Structured billing events keep their existing logging path. + +The server generates one request ID before authentication and uses it in completion logs and +the command's diagnostic trace. Client headers and metadata cannot choose that ID. + +Raw framework traffic logging is disabled. The `mcp-safe-logging` filter also discards that category +if `quarkus.mcp.server.traffic-logging.enabled` is overridden. It is attached to the standard console, +file, syslog and socket handlers. Any added handler or log exporter must apply the same filter +before publishing records. Keep these filters in deployment overrides. The MCP endpoint and its +access-log exclusion are derived together from `quarkus.http.root-path` and +`quarkus.mcp.server.http.root-path`. Changing either path requires no separate logging configuration. +Keep the authentication path configuration aligned with the endpoint. Explicit +`quarkus.http.access-log.exclude-pattern` overrides replace the generated exclusion and must also +exclude the MCP endpoint and its descendants. Ordinary HTTP API logging is unaffected. + +For a diagnostic session, set `stargate.jsonapi.mcp.diagnostics-until` (environment variable +`STARGATE_JSONAPI_MCP_DIAGNOSTICS_UNTIL`) to an absolute ISO-8601 UTC timestamp no more than 15 minutes +in the future at startup. Diagnostics add at most 32 stack frames per exception. They expire at +that timestamp, including across restarts. Payloads, credentials, exception messages, causes and +suppressed exceptions remain excluded. There is no payload-capture mode. + +Before enabling diagnostics, restrict access to the log destination and configure diagnostic log +retention to at most 24 hours. Remove the setting after the session and delete diagnostic exports +when the investigation ends. Retention is enforced by the log destination, not by this service. +Deployment verification must check the effective handlers, access-log exclusion and retention +through the public service. OAuth authorization-service logs require separate verification when +that service is integrated. + ## API Feature enabling configuration *Configuration for enabling Features, defined by [FeaturesConfig.java](src/main/java/io/stargate/sgv2/jsonapi/config/CommandLoggingConfig.java).* diff --git a/src/main/java/io/stargate/sgv2/jsonapi/api/request/RequestContext.java b/src/main/java/io/stargate/sgv2/jsonapi/api/request/RequestContext.java index 29868fe35a..e0c770d6b4 100644 --- a/src/main/java/io/stargate/sgv2/jsonapi/api/request/RequestContext.java +++ b/src/main/java/io/stargate/sgv2/jsonapi/api/request/RequestContext.java @@ -40,6 +40,7 @@ public class RequestContext implements LoggingMDCContext { private static final NoArgGenerator UUID_V7_GENERATOR = Generators.timeBasedEpochGenerator(); + private static final String ROUTING_REQUEST_ID = RequestContext.class.getName() + ".requestId"; private final String authToken; private final String requestId; @@ -91,7 +92,7 @@ public RequestContext( securityIdentity.getPrincipal() != null ? securityIdentity.getPrincipal().getName() : null); - this.requestId = generateRequestId(); + this.requestId = getOrCreateRequestId(routingContext); this.userAgent = new UserAgent(httpHeaders.getHeader(HttpHeaders.USER_AGENT)); this.tenant = tenantResolver.get().resolve(routingContext, null); @@ -135,6 +136,19 @@ private static String generateRequestId() { return UUID_V7_GENERATOR.generate().toString(); } + /** + * Returns the server-generated ID shared by early MCP logging and the command's diagnostic trace. + * Routing data retains it across callbacks without reading client headers or metadata. + */ + public static String getOrCreateRequestId(RoutingContext routingContext) { + String requestId = routingContext.get(ROUTING_REQUEST_ID); + if (requestId == null) { + requestId = generateRequestId(); + routingContext.put(ROUTING_REQUEST_ID, requestId); + } + return requestId; + } + /** * String correlation ID for the request, generated at the start of the request processing. * diff --git a/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/GeneralCommandTools.java b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/GeneralCommandTools.java index c50fb114a6..e04310f4ea 100644 --- a/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/GeneralCommandTools.java +++ b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/GeneralCommandTools.java @@ -27,7 +27,7 @@ public Uni createKeyspace( CreateKeyspaceCommand.Options options) { var command = new CreateKeyspaceCommand(name, options); - return mcpResource.processCommand(mcpResource.buildDatabaseContext(command), command); + return mcpResource.processCommand(() -> mcpResource.buildDatabaseContext(command), command); } @Tool(description = "Command that deletes a Keyspace.") @@ -35,14 +35,14 @@ public Uni dropKeyspace( @ToolArg(description = "Name of the keyspace to drop") @NotEmpty String name) { var command = new DropKeyspaceCommand(name); - return mcpResource.processCommand(mcpResource.buildDatabaseContext(command), command); + return mcpResource.processCommand(() -> mcpResource.buildDatabaseContext(command), command); } @Tool(description = "Command that lists all available keyspaces") public Uni findKeyspaces() { var command = new FindKeyspacesCommand(); - return mcpResource.processCommand(mcpResource.buildDatabaseContext(command), command); + return mcpResource.processCommand(() -> mcpResource.buildDatabaseContext(command), command); } @Tool(description = "Lists the available Embedding Providers for this database.") @@ -54,7 +54,7 @@ public Uni findEmbeddingProviders( FindEmbeddingProvidersCommand.Options options) { var command = new FindEmbeddingProvidersCommand(options); - return mcpResource.processCommand(mcpResource.buildDatabaseContext(command), command); + return mcpResource.processCommand(() -> mcpResource.buildDatabaseContext(command), command); } @Tool(description = "Lists the available Reranking Providers for this database.") @@ -66,6 +66,6 @@ public Uni findRerankingProviders( FindRerankingProvidersCommand.Options options) { var command = new FindRerankingProvidersCommand(options); - return mcpResource.processCommand(mcpResource.buildDatabaseContext(command), command); + return mcpResource.processCommand(() -> mcpResource.buildDatabaseContext(command), command); } } diff --git a/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/KeyspaceCommandTools.java b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/KeyspaceCommandTools.java index b637e54eb0..1d2518b35d 100644 --- a/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/KeyspaceCommandTools.java +++ b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/KeyspaceCommandTools.java @@ -33,7 +33,8 @@ public Uni createCollection( CreateCollectionCommand.Options options) { var command = new CreateCollectionCommand(collection, options); - return mcpResource.processCommand(mcpResource.buildKeyspaceContext(keyspace, command), command); + return mcpResource.processCommand( + () -> mcpResource.buildKeyspaceContext(keyspace, command), command); } @Tool(description = "Command that deletes a collection if one exists.") @@ -42,7 +43,8 @@ public Uni deleteCollection( @ToolArg(description = "Name of the collection to delete") String collection) { var command = new DeleteCollectionCommand(collection); - return mcpResource.processCommand(mcpResource.buildKeyspaceContext(keyspace, command), command); + return mcpResource.processCommand( + () -> mcpResource.buildKeyspaceContext(keyspace, command), command); } @Tool(description = "Command that lists all available collections in a keyspace.") @@ -54,7 +56,8 @@ public Uni findCollections( FindCollectionsCommand.Options options) { var command = new FindCollectionsCommand(options); - return mcpResource.processCommand(mcpResource.buildKeyspaceContext(keyspace, command), command); + return mcpResource.processCommand( + () -> mcpResource.buildKeyspaceContext(keyspace, command), command); } /** @@ -76,7 +79,8 @@ public Uni alterType( TypeDefinitionDesc add) { var command = new AlterTypeCommand(name, rename, add); - return mcpResource.processCommand(mcpResource.buildKeyspaceContext(keyspace, command), command); + return mcpResource.processCommand( + () -> mcpResource.buildKeyspaceContext(keyspace, command), command); } @Tool(description = "Command that creates an API Table.") @@ -93,7 +97,8 @@ public Uni createTable( CreateTableCommand.Options options) { var command = new CreateTableCommand(table, definition, options); - return mcpResource.processCommand(mcpResource.buildKeyspaceContext(keyspace, command), command); + return mcpResource.processCommand( + () -> mcpResource.buildKeyspaceContext(keyspace, command), command); } @Tool(description = "Command that creates a user defined type.") @@ -110,7 +115,8 @@ public Uni createType( CreateTypeCommand.Options options) { var command = new CreateTypeCommand(name, definition, options); - return mcpResource.processCommand(mcpResource.buildKeyspaceContext(keyspace, command), command); + return mcpResource.processCommand( + () -> mcpResource.buildKeyspaceContext(keyspace, command), command); } @Tool(description = "Command that drops an index for a column.") @@ -123,7 +129,8 @@ public Uni dropIndex( DropIndexCommand.Options options) { var command = new DropIndexCommand(name, options); - return mcpResource.processCommand(mcpResource.buildKeyspaceContext(keyspace, command), command); + return mcpResource.processCommand( + () -> mcpResource.buildKeyspaceContext(keyspace, command), command); } @Tool(description = "Command that drops a table if one exists.") @@ -136,7 +143,8 @@ public Uni dropTable( DropTableCommand.Options options) { var command = new DropTableCommand(table, options); - return mcpResource.processCommand(mcpResource.buildKeyspaceContext(keyspace, command), command); + return mcpResource.processCommand( + () -> mcpResource.buildKeyspaceContext(keyspace, command), command); } @Tool(description = "Command that drops a user defined type if one exists.") @@ -149,7 +157,8 @@ public Uni dropType( DropTypeCommand.Options options) { var command = new DropTypeCommand(name, options); - return mcpResource.processCommand(mcpResource.buildKeyspaceContext(keyspace, command), command); + return mcpResource.processCommand( + () -> mcpResource.buildKeyspaceContext(keyspace, command), command); } @Tool(description = "Command that lists all available tables in a keyspace") @@ -161,7 +170,8 @@ public Uni listTables( ListTablesCommand.Options options) { var command = new ListTablesCommand(options); - return mcpResource.processCommand(mcpResource.buildKeyspaceContext(keyspace, command), command); + return mcpResource.processCommand( + () -> mcpResource.buildKeyspaceContext(keyspace, command), command); } @Tool(description = "Command that lists all available types in a keyspace") @@ -173,6 +183,7 @@ public Uni listTypes( ListTypesCommand.Options options) { var command = new ListTypesCommand(options); - return mcpResource.processCommand(mcpResource.buildKeyspaceContext(keyspace, command), command); + return mcpResource.processCommand( + () -> mcpResource.buildKeyspaceContext(keyspace, command), command); } } diff --git a/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpEndpointConfigSourceFactory.java b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpEndpointConfigSourceFactory.java new file mode 100644 index 0000000000..fcb0d65fb2 --- /dev/null +++ b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpEndpointConfigSourceFactory.java @@ -0,0 +1,51 @@ +package io.stargate.sgv2.jsonapi.api.v1.mcp; + +import io.quarkus.runtime.annotations.StaticInitSafe; +import io.smallrye.config.ConfigSourceContext; +import io.smallrye.config.ConfigSourceFactory; +import io.smallrye.config.PropertiesConfigSource; +import java.net.URI; +import java.util.List; +import java.util.Map; +import java.util.regex.Pattern; +import org.eclipse.microprofile.config.spi.ConfigSource; + +/** Shares the normalized MCP endpoint with request logging and Quarkus access logging. */ +@StaticInitSafe +public class McpEndpointConfigSourceFactory implements ConfigSourceFactory { + static final String ENDPOINT_PATH = "stargate.jsonapi.mcp.endpoint-path"; + + @Override + public Iterable getConfigSources(ConfigSourceContext context) { + String mcpRoot = context.getValue("quarkus.mcp.server.http.root-path").getValue(); + if (mcpRoot == null) { + // Quarkus also builds bootstrap configurations before application configuration is loaded. + return List.of(); + } + String httpRoot = context.getValue("quarkus.http.root-path").getValue(); + httpRoot = httpRoot == null ? "/" : httpRoot.replace("//", "/"); + httpRoot = httpRoot.endsWith("/") ? httpRoot : httpRoot + "/"; + mcpRoot = mcpRoot.startsWith("/") ? mcpRoot.substring(1) : mcpRoot; + // Match Quarkus route normalization, including its treatment of repeated leading slashes. + URI mcpUri = URI.create(mcpRoot.replace("//", "/")).normalize(); + if (mcpUri.getPath().isEmpty()) { + mcpUri = URI.create(""); + } + String endpointPath = URI.create(httpRoot).resolve(mcpUri).normalize().getPath(); + if (endpointPath.endsWith("/") && endpointPath.length() > 1) { + endpointPath = endpointPath.substring(0, endpointPath.length() - 1); + } + String excludePattern = + Pattern.quote(endpointPath) + (endpointPath.equals("/") ? ".*" : "(/.*)?"); + // A config source is needed because Quarkus creates its access logger before CDI startup. + // The default source ordinal leaves explicit operator exclusions at their normal precedence. + return List.of( + new PropertiesConfigSource( + Map.of( + ENDPOINT_PATH, + endpointPath, + "quarkus.http.access-log.exclude-pattern", + excludePattern), + "MCP endpoint")); + } +} diff --git a/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingFilter.java b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingFilter.java new file mode 100644 index 0000000000..af10050aa5 --- /dev/null +++ b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingFilter.java @@ -0,0 +1,103 @@ +package io.stargate.sgv2.jsonapi.api.v1.mcp; + +import io.quarkus.logging.LoggingFilter; +import jakarta.inject.Inject; +import java.time.Clock; +import java.time.Duration; +import java.time.Instant; +import java.time.format.DateTimeParseException; +import java.util.Arrays; +import java.util.HashMap; +import java.util.Optional; +import java.util.logging.Filter; +import java.util.logging.LogRecord; +import org.eclipse.microprofile.config.inject.ConfigProperty; +import org.jboss.logmanager.ExtLogRecord; + +/** + * Keeps free-form messages, parameters, exception messages and context out of MCP logs. Applying + * this at the handler also covers framework parsing errors and asynchronous command failures. + */ +@LoggingFilter(name = "mcp-safe-logging") +public final class McpLoggingFilter implements Filter { + private static final String SAFE_LOGGER = McpRequestLogging.class.getName(); + static final String EXCEPTION_TYPE = "mcpExceptionType"; + private final Instant diagnosticsUntil; + private final Clock clock; + + @Inject + public McpLoggingFilter( + @ConfigProperty(name = "stargate.jsonapi.mcp.diagnostics-until") + Optional diagnosticsUntil) { + this(diagnosticsUntil, Clock.systemUTC()); + } + + McpLoggingFilter(Optional diagnosticsUntil, Clock clock) { + this.clock = clock; + try { + this.diagnosticsUntil = diagnosticsUntil.map(Instant::parse).orElse(Instant.MIN); + } catch (DateTimeParseException e) { + // Do not include an invalid configuration value in an error message. + throw new IllegalArgumentException("MCP diagnostics-until must be an ISO-8601 timestamp"); + } + if (this.diagnosticsUntil.isAfter(clock.instant().plus(Duration.ofMinutes(15)))) { + throw new IllegalArgumentException("MCP diagnostics may be enabled for at most 15 minutes"); + } + } + + @Override + public boolean isLoggable(LogRecord record) { + String logger = record.getLoggerName(); + // Raw traffic logging must stay off even if an operator enables the framework setting. + if ("io.quarkus.mcp.server.traffic".equals(logger)) { + return false; + } + var extended = record instanceof ExtLogRecord r ? r : null; + String requestId = extended == null ? null : extended.getMdc(McpRequestLogging.REQUEST_ID); + boolean framework = logger != null && logger.startsWith("io.quarkiverse.mcp.server."); + if ((!framework && requestId == null) || "billing.events".equals(logger)) { + return true; + } + + Throwable failure = record.getThrown(); + // A record can pass through this filter on multiple handlers. Preserve the original type + // after the first handler has removed or replaced the throwable. + String exceptionType = extended == null ? null : extended.getMdc(EXCEPTION_TYPE); + if (exceptionType == null && failure != null) { + exceptionType = failure.getClass().getName(); + } + + // MDC/NDC may include user-controlled tenant, collection and other input values. + if (extended != null) { + var safeContext = new HashMap(); + if (requestId != null) { + safeContext.put(McpRequestLogging.REQUEST_ID, requestId); + } + if (exceptionType != null) { + safeContext.put(EXCEPTION_TYPE, exceptionType); + } + extended.setMdc(safeContext); + extended.setNdc(""); + extended.setMarker(null); + } + if (SAFE_LOGGER.equals(logger)) { + return true; + } + + record.setMessage( + "MCP event details redacted" + + (exceptionType == null ? "" : "; exception=" + exceptionType)); + record.setParameters(null); + record.setResourceBundle(null); + record.setResourceBundleName(null); + record.setThrown(null); + if (failure != null && clock.instant().isBefore(diagnosticsUntil)) { + // Preserve stack locations without copying messages, causes or suppressed exceptions. + Throwable safeFailure = new Throwable("MCP diagnostic stack (details redacted)"); + safeFailure.setStackTrace( + Arrays.stream(failure.getStackTrace()).limit(32).toArray(StackTraceElement[]::new)); + record.setThrown(safeFailure); + } + return true; + } +} diff --git a/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpRequestContextProvider.java b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpRequestContextProvider.java new file mode 100644 index 0000000000..c298ad0d2e --- /dev/null +++ b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpRequestContextProvider.java @@ -0,0 +1,42 @@ +package io.stargate.sgv2.jsonapi.api.v1.mcp; + +import java.util.Map; +import org.eclipse.microprofile.context.spi.ThreadContextProvider; +import org.eclipse.microprofile.context.spi.ThreadContextSnapshot; +import org.slf4j.MDC; + +/** + * Keeps the MCP request identifier across asynchronous callbacks without copying other MDC data. + */ +public final class McpRequestContextProvider implements ThreadContextProvider { + @Override + public ThreadContextSnapshot currentContext(Map props) { + return snapshot(MDC.get(McpRequestLogging.REQUEST_ID)); + } + + @Override + public ThreadContextSnapshot clearedContext(Map props) { + return snapshot(null); + } + + @Override + public String getThreadContextType() { + return McpRequestLogging.REQUEST_ID; + } + + private static ThreadContextSnapshot snapshot(String requestId) { + return () -> { + String previous = MDC.get(McpRequestLogging.REQUEST_ID); + setRequestId(requestId); + return () -> setRequestId(previous); + }; + } + + private static void setRequestId(String requestId) { + if (requestId == null) { + MDC.remove(McpRequestLogging.REQUEST_ID); + } else { + MDC.put(McpRequestLogging.REQUEST_ID, requestId); + } + } +} diff --git a/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpRequestLogging.java b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpRequestLogging.java new file mode 100644 index 0000000000..da573b0d6d --- /dev/null +++ b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpRequestLogging.java @@ -0,0 +1,79 @@ +package io.stargate.sgv2.jsonapi.api.v1.mcp; + +import io.quarkiverse.mcp.server.ToolResponse; +import io.quarkus.vertx.http.runtime.filters.Filters; +import io.stargate.sgv2.jsonapi.api.model.command.Command; +import io.stargate.sgv2.jsonapi.api.request.RequestContext; +import io.vertx.ext.web.RoutingContext; +import jakarta.enterprise.context.ApplicationScoped; +import jakarta.enterprise.event.Observes; +import java.util.Set; +import org.eclipse.microprofile.config.inject.ConfigProperty; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; +import org.slf4j.MDC; + +/** Records MCP outcomes using server-generated identifiers and fixed categories only. */ +@ApplicationScoped +public class McpRequestLogging { + static final String REQUEST_ID = "mcpRequestId"; + private static final Logger LOGGER = LoggerFactory.getLogger(McpRequestLogging.class); + private static final Set METHODS = Set.of("server/discover", "tools/list", "tools/call"); + + @ConfigProperty(name = McpEndpointConfigSourceFactory.ENDPOINT_PATH) + String endpointPath; + + void register(@Observes Filters filters) { + // Run before authentication and MCP parsing, so failures there are protected too. + filters.register(this::handle, Integer.MAX_VALUE); + } + + void handle(RoutingContext context) { + String path = context.normalizedPath(); + if (!endpointPath.equals("/") + && !path.equals(endpointPath) + && !path.startsWith(endpointPath + "/")) { + context.next(); + return; + } + String requestId = RequestContext.getOrCreateRequestId(context); + String header = context.request().getHeader("Mcp-Method"); + String method = header != null && METHODS.contains(header) ? header : "other"; + MDC.put(REQUEST_ID, requestId); + context.addEndHandler( + ignored -> { + LOGGER.info( + "MCP request completed requestId={} method={} status={}", + requestId, + method, + context.response().getStatusCode()); + MDC.remove(REQUEST_ID); + }); + context.next(); + } + + static void activate(RoutingContext context) { + // The framework runs tools in a new duplicated Vert.x context, without the HTTP MDC. + // RoutingContext data survives that boundary and the ID never comes from client input. + MDC.put(REQUEST_ID, RequestContext.getOrCreateRequestId(context)); + } + + static void commandCompleted(Command command, ToolResponse result) { + LOGGER.info( + "MCP command completed requestId={} command={} isError={}", + MDC.get(REQUEST_ID), + command.commandName().getApiName(), + result.isError()); + } + + static void setupFailed() { + LOGGER.warn("MCP setup failed requestId={} category=unexpected", MDC.get(REQUEST_ID)); + } + + static void commandFailed(Command command) { + LOGGER.warn( + "MCP command failed requestId={} command={}", + MDC.get(REQUEST_ID), + command.commandName().getApiName()); + } +} diff --git a/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpResource.java b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpResource.java index 079730fff8..0545054a74 100644 --- a/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpResource.java +++ b/src/main/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpResource.java @@ -38,6 +38,7 @@ import jakarta.ws.rs.WebApplicationException; import java.util.concurrent.CancellationException; import java.util.concurrent.CompletionException; +import java.util.function.Supplier; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -157,82 +158,95 @@ public Uni> buildKeyspaceContext(String keyspace, KeyspaceComm */ public Uni processCollectionCommand( String keyspace, String collection, CollectionCommand command) { - Uni> contextUni = - Uni.createFrom() - .deferred( - () -> { - var requestContext = createRequestContext(); - var unscopedSchemaIdentifier = - new UnscopedSchemaObjectIdentifier.DefaultKeyspaceScopedName( - cqlIdentifierFromUserInput(keyspace), - cqlIdentifierFromUserInput(collection)); + return processCommand( + () -> { + var requestContext = createRequestContext(); + var unscopedSchemaIdentifier = + new UnscopedSchemaObjectIdentifier.DefaultKeyspaceScopedName( + cqlIdentifierFromUserInput(keyspace), cqlIdentifierFromUserInput(collection)); - return schemaObjectCacheSupplier - .get() - .getTableBased( - requestContext, - unscopedSchemaIdentifier, - requestContext.userAgent(), - command.isForceSchemaRefresh()) - .map( - schemaObject -> { - VectorColumnDefinition vectorColDef = null; - if (schemaObject.type() == SchemaObjectType.COLLECTION) { - vectorColDef = - schemaObject - .vectorConfig() - .getColumnDefinition(VECTOR_EMBEDDING_TEXT_FIELD) - .orElse(null); - } else if (schemaObject.type() == SchemaObjectType.TABLE) { - vectorColDef = - schemaObject - .vectorConfig() - .getFirstVectorColumnWithVectorizeDefinition() - .orElse(null); - } + return schemaObjectCacheSupplier + .get() + .getTableBased( + requestContext, + unscopedSchemaIdentifier, + requestContext.userAgent(), + command.isForceSchemaRefresh()) + .map( + schemaObject -> { + VectorColumnDefinition vectorColDef = null; + if (schemaObject.type() == SchemaObjectType.COLLECTION) { + vectorColDef = + schemaObject + .vectorConfig() + .getColumnDefinition(VECTOR_EMBEDDING_TEXT_FIELD) + .orElse(null); + } else if (schemaObject.type() == SchemaObjectType.TABLE) { + vectorColDef = + schemaObject + .vectorConfig() + .getFirstVectorColumnWithVectorizeDefinition() + .orElse(null); + } - EmbeddingProvider embeddingProvider = null; - if (vectorColDef != null - && vectorColDef.vectorizeDefinition() != null) { - embeddingProvider = - embeddingProviderFactory.create( - requestContext.tenant(), - requestContext.authToken(), - vectorColDef.vectorizeDefinition().provider(), - vectorColDef.vectorizeDefinition().modelName(), - vectorColDef.vectorSize(), - vectorColDef.vectorizeDefinition().parameters(), - vectorColDef.vectorizeDefinition().authentication(), - command.getClass().getSimpleName()); - } + EmbeddingProvider embeddingProvider = null; + if (vectorColDef != null && vectorColDef.vectorizeDefinition() != null) { + embeddingProvider = + embeddingProviderFactory.create( + requestContext.tenant(), + requestContext.authToken(), + vectorColDef.vectorizeDefinition().provider(), + vectorColDef.vectorizeDefinition().modelName(), + vectorColDef.vectorSize(), + vectorColDef.vectorizeDefinition().parameters(), + vectorColDef.vectorizeDefinition().authentication(), + command.getClass().getSimpleName()); + } - return contextBuilderSupplier - .getBuilder(schemaObject) - .withEmbeddingProvider(embeddingProvider) - .withCommandName(command.getClass().getSimpleName()) - .withRequestContext(requestContext) - .build(); - }); - }); - return processCommand(contextUni, command); + return contextBuilderSupplier + .getBuilder(schemaObject) + .withEmbeddingProvider(embeddingProvider) + .withCommandName(command.getClass().getSimpleName()) + .withRequestContext(requestContext) + .build(); + }); + }, + command); } /** * Normalize context setup failures, then process a command and map its result to an MCP tool * response. * - * @param contextUni The command context + * @param contextSupplier Builds the command context after request logging is active * @param command The command to execute * @return Uni of ToolResponse */ - public Uni processCommand(Uni> contextUni, Command command) { - - return contextUni - .onItemOrFailure() - .transformToUni( - (context, failure) -> - failure == null ? executeCommand(context, command) : handleSetupFailure(failure)) - .map(CommandResult::toToolResponse); + public Uni processCommand( + Supplier>> contextSupplier, Command command) { + return Uni.createFrom() + .deferred( + () -> { + Uni> contextUni; + try { + // Mutiny captures context when callbacks are assembled. + McpRequestLogging.activate(routingContextProvider.get()); + contextUni = contextSupplier.get(); + } catch (Exception failure) { + contextUni = Uni.createFrom().failure(failure); + } + return contextUni + .onItemOrFailure() + .transformToUni( + (context, failure) -> + failure == null + ? executeCommand(context, command) + : handleSetupFailure(failure)) + .map(CommandResult::toToolResponse) + .invoke(result -> McpRequestLogging.commandCompleted(command, result)) + .onFailure() + .invoke(failure -> McpRequestLogging.commandFailed(command)); + }); } private Uni executeCommand(CommandContext context, Command command) { @@ -287,6 +301,9 @@ private Uni handleSetupFailure(Throwable failure) { // Only APIException messages are intended for clients. Arbitrary setup failures may include // credentials or provider payloads, so do not pass them to the generic throwable mapper. + if (!(failure instanceof APIException)) { + McpRequestLogging.setupFailed(); + } var error = failure instanceof APIException apiException ? apiException diff --git a/src/main/java/io/stargate/sgv2/jsonapi/service/cqldriver/CqlSessionFactory.java b/src/main/java/io/stargate/sgv2/jsonapi/service/cqldriver/CqlSessionFactory.java index de2ef16e0c..49dfb8b70a 100644 --- a/src/main/java/io/stargate/sgv2/jsonapi/service/cqldriver/CqlSessionFactory.java +++ b/src/main/java/io/stargate/sgv2/jsonapi/service/cqldriver/CqlSessionFactory.java @@ -10,6 +10,7 @@ import com.typesafe.config.Config; import com.typesafe.config.ConfigFactory; import com.typesafe.config.ConfigRenderOptions; +import io.smallrye.mutiny.Uni; import io.stargate.sgv2.jsonapi.api.request.tenant.Tenant; import io.stargate.sgv2.jsonapi.config.DatabaseType; import io.stargate.sgv2.jsonapi.exception.DatabaseException; @@ -25,8 +26,6 @@ import java.util.concurrent.CompletableFuture; import java.util.concurrent.CompletionException; import java.util.concurrent.CompletionStage; -import java.util.function.BiFunction; -import java.util.function.Function; import java.util.function.Supplier; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -218,28 +217,19 @@ public CompletionStage apply(Tenant tenant, CqlCredentials credentia // Add optimized CqlVector codec (see [data-api#1775]) builder = builder.addTypeCodecs(SubtypeOnlyFloatVectorToArrayCodec.instance()); - // when we are handling the result of the buildAsync() we need the tenant passed along. - // simple recompose the functions so they match signature from the framework - BiFunction partialUnwrapBuildException = - (session, throwable) -> unwrapBuildException(tenant, session, throwable); - Function> partialValidateSession = - (session) -> validateSession(tenant, session); - - return builder - .buildAsync() - .handle(partialUnwrapBuildException) - .thenCompose(partialValidateSession); + // Uni callbacks preserve the request context when the driver completes session creation. + return Uni.createFrom() + .completionStage(builder.buildAsync()) + .onFailure() + .transform(throwable -> mapBuildFailure(tenant, throwable)) + .flatMap(session -> Uni.createFrom().completionStage(validateSession(tenant, session))) + .subscribeAsCompletionStage() + // Preserve the dependent stage's cancellation isolation from session creation. + .copy(); } - /** - * Process any throwable that was thrown from buildAsync(), pass through the session if no error. - */ - private static CqlSession unwrapBuildException( - Tenant tenant, CqlSession cqlSession, Throwable throwable) { - - if (throwable == null) { - return cqlSession; - } + /** Maps a failed session creation to the corresponding Data API error. */ + private static Throwable mapBuildFailure(Tenant tenant, Throwable throwable) { // there was an error starting the session, often a token is invalid // When the driver throws it's error passes through CompletionStage's and so is @@ -250,7 +240,7 @@ private static CqlSession unwrapBuildException( ? throwable.getCause() : throwable; LOGGER.debug( - "unwrapBuildException() - throwable not null. tenant={}, throwable={}, toHandle={}", + "mapBuildFailure() - throwable not null. tenant={}, throwable={}, toHandle={}", tenant, throwable.toString(), toHandle.toString()); @@ -258,10 +248,8 @@ private static CqlSession unwrapBuildException( var err = new DatabaseDriverExceptionHandler(new DatabaseSchemaObject(tenant)).maybeHandle(toHandle); LOGGER.debug( - "unwrapBuildException() - session build error mapped to APIException. tenant={}", - tenant, - err); - throw err; + "mapBuildFailure() - session build error mapped to APIException. tenant={}", tenant, err); + return err; } /** @@ -328,9 +316,10 @@ private static CompletionStage validateSession(Tenant tenant, CqlSes // NOTE: while throwing the error will prevent the session from getting into the // CqlSessionCache we use ExceptionFlags.UNRELIABLE_DB_SESSION tells the CommandProcessor we // want to evict the session when from cache when the request is over as belt and braces - return cqlSession - .closeAsync() - .handle( + return Uni.createFrom() + .completionStage(cqlSession.closeAsync()) + .onItemOrFailure() + .transformToUni( (ignored, closeError) -> { if (closeError != null) { LOGGER.error( @@ -339,8 +328,13 @@ private static CompletionStage validateSession(Tenant tenant, CqlSes closeError); } // this is the real error we want to get back to the user - throw DatabaseException.Code.FAILED_TO_READ_METADATA.get( - EnumSet.of(ExceptionFlags.UNRELIABLE_DB_SESSION)); - }); + return Uni.createFrom() + .failure( + DatabaseException.Code.FAILED_TO_READ_METADATA.get( + EnumSet.of(ExceptionFlags.UNRELIABLE_DB_SESSION))); + }) + .subscribeAsCompletionStage() + // The invalid session still needs to close if its caller cancels. + .copy(); } } diff --git a/src/main/java/io/stargate/sgv2/jsonapi/util/DynamicTTLCache.java b/src/main/java/io/stargate/sgv2/jsonapi/util/DynamicTTLCache.java index e1716dc540..89b72ea781 100644 --- a/src/main/java/io/stargate/sgv2/jsonapi/util/DynamicTTLCache.java +++ b/src/main/java/io/stargate/sgv2/jsonapi/util/DynamicTTLCache.java @@ -228,11 +228,10 @@ private CompletableFuture> onLoadValue(KeyT key, Execu new IllegalStateException("valueFactory returned null CompletionStage for key: " + key)); } - return stage - // if completed exceptionally, it is wrapped in a CompletionStage that is also completed - // exceptionally - .exceptionallyCompose(CompletableFuture::failedFuture) - .thenApply( + // Uni callbacks preserve the request context when the loader completes on a driver thread. + return Uni.createFrom() + .completionStage(stage) + .map( value -> { if (value == null) { // sanity check @@ -245,7 +244,9 @@ private CompletableFuture> onLoadValue(KeyT key, Execu } return holder; }) - .toCompletableFuture(); + .subscribeAsCompletionStage() + // Keep cancellation of a dependent cache future from canceling the loader itself. + .copy(); } /** diff --git a/src/main/resources/META-INF/services/io.smallrye.config.ConfigSourceFactory b/src/main/resources/META-INF/services/io.smallrye.config.ConfigSourceFactory new file mode 100644 index 0000000000..19786e146a --- /dev/null +++ b/src/main/resources/META-INF/services/io.smallrye.config.ConfigSourceFactory @@ -0,0 +1 @@ +io.stargate.sgv2.jsonapi.api.v1.mcp.McpEndpointConfigSourceFactory diff --git a/src/main/resources/META-INF/services/org.eclipse.microprofile.context.spi.ThreadContextProvider b/src/main/resources/META-INF/services/org.eclipse.microprofile.context.spi.ThreadContextProvider new file mode 100644 index 0000000000..b3f42e811d --- /dev/null +++ b/src/main/resources/META-INF/services/org.eclipse.microprofile.context.spi.ThreadContextProvider @@ -0,0 +1 @@ +io.stargate.sgv2.jsonapi.api.v1.mcp.McpRequestContextProvider diff --git a/src/main/resources/application.yaml b/src/main/resources/application.yaml index 13bb2c0bed..9ca7711e55 100644 --- a/src/main/resources/application.yaml +++ b/src/main/resources/application.yaml @@ -87,6 +87,7 @@ quarkus: access-log: enabled: true pattern: "%h %l %t \"%r\" %s %b" + # McpEndpointConfigSourceFactory excludes the effective MCP path from access logs. # every /v1 path is authenticated by default # adapt if changing the authentication mechanism @@ -114,6 +115,13 @@ quarkus: log: console: format: "%-5p [%t] %d{yyyy-MM-dd HH:mm:ss,SSS} %c:%L - %m%n" + filter: mcp-safe-logging + file: + filter: mcp-safe-logging + syslog: + filter: mcp-safe-logging + socket: + filter: mcp-safe-logging handler: console: @@ -222,8 +230,8 @@ quarkus: # https://docs.quarkiverse.io/quarkus-mcp-server/1.13.x/reference-configuration.html#quarkus-mcp-server-http_quarkus-mcp-server-http-streamable-auto-init auto-init: true traffic-logging: - enabled: true - text-limit: 1000 + # Never log raw MCP messages, even for diagnostics. + enabled: false "%dev": quarkus: diff --git a/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpCustomPathLoggingTest.java b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpCustomPathLoggingTest.java new file mode 100644 index 0000000000..d4cee6bdf6 --- /dev/null +++ b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpCustomPathLoggingTest.java @@ -0,0 +1,22 @@ +package io.stargate.sgv2.jsonapi.api.v1.mcp; + +import io.quarkus.test.junit.QuarkusTest; +import io.quarkus.test.junit.TestProfile; +import java.util.HashMap; +import java.util.Map; + +@QuarkusTest +@TestProfile(McpCustomPathLoggingTest.CustomPathProfile.class) +class McpCustomPathLoggingTest extends McpLoggingTest { + public static class CustomPathProfile extends LoggingProfile { + @Override + public Map getConfigOverrides() { + var overrides = new HashMap<>(super.getConfigOverrides()); + overrides.put("quarkus.http.root-path", "/service"); + overrides.put("quarkus.mcp.server.http.root-path", "/tools"); + overrides.put( + "quarkus.http.auth.permission.default.paths", "/service/tools,/service/tools/*"); + return overrides; + } + } +} diff --git a/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpDiagnosticLoggingTest.java b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpDiagnosticLoggingTest.java new file mode 100644 index 0000000000..ea82e47c36 --- /dev/null +++ b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpDiagnosticLoggingTest.java @@ -0,0 +1,24 @@ +package io.stargate.sgv2.jsonapi.api.v1.mcp; + +import io.quarkus.test.junit.QuarkusTest; +import io.quarkus.test.junit.TestProfile; +import java.time.Instant; +import java.util.HashMap; +import java.util.Map; + +/** Repeats the HTTP regressions with framework diagnostics and raw traffic explicitly enabled. */ +@QuarkusTest +@TestProfile(McpDiagnosticLoggingTest.DiagnosticProfile.class) +class McpDiagnosticLoggingTest extends McpLoggingTest { + public static class DiagnosticProfile extends LoggingProfile { + @Override + public Map getConfigOverrides() { + var overrides = new HashMap<>(super.getConfigOverrides()); + overrides.put( + "stargate.jsonapi.mcp.diagnostics-until", Instant.now().plusSeconds(300).toString()); + overrides.put("quarkus.mcp.server.traffic-logging.enabled", "true"); + overrides.put("quarkus.log.category.\"io.quarkiverse.mcp.server\".level", "DEBUG"); + return overrides; + } + } +} diff --git a/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpEndpointConfigSourceFactoryTest.java b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpEndpointConfigSourceFactoryTest.java new file mode 100644 index 0000000000..601b0c0726 --- /dev/null +++ b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpEndpointConfigSourceFactoryTest.java @@ -0,0 +1,69 @@ +package io.stargate.sgv2.jsonapi.api.v1.mcp; + +import static org.assertj.core.api.Assertions.assertThat; + +import io.smallrye.config.PropertiesConfigSource; +import io.smallrye.config.SmallRyeConfig; +import io.smallrye.config.SmallRyeConfigBuilder; +import java.util.Map; +import java.util.regex.Pattern; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.CsvSource; + +class McpEndpointConfigSourceFactoryTest { + @ParameterizedTest + @CsvSource({ + "/, /v1/mcp, /v1/mcp", + "/service, /tools, /service/tools", + "//service, /tools, /service/tools", + "/service, //tools, /tools", + "/service, ///tools, /tools", + "/service, ////tools, /service", + "/service/, tools/, /service/tools", + "/service.v1, /tools, /service.v1/tools" + }) + void excludesOnlyTheNormalizedEndpointAndItsDescendants( + String httpRoot, String mcpRoot, String expectedEndpoint) { + var config = + config( + Map.of( + "quarkus.http.root-path", httpRoot, + "quarkus.mcp.server.http.root-path", mcpRoot)); + assertThat(config.getValue(McpEndpointConfigSourceFactory.ENDPOINT_PATH, String.class)) + .isEqualTo(expectedEndpoint); + var excluded = + Pattern.compile(config.getValue("quarkus.http.access-log.exclude-pattern", String.class)); + assertThat(excluded.matcher(expectedEndpoint).matches()).isTrue(); + assertThat(excluded.matcher(expectedEndpoint + "/messages").matches()).isTrue(); + assertThat(excluded.matcher(expectedEndpoint + "-other").matches()).isFalse(); + assertThat(excluded.matcher("/serviceXv1/tools").matches()).isFalse(); + } + + @Test + void rootEndpointExcludesAllDescendants() { + var config = config(Map.of("quarkus.mcp.server.http.root-path", "/")); + var excluded = + Pattern.compile(config.getValue("quarkus.http.access-log.exclude-pattern", String.class)); + assertThat(excluded.matcher("/").matches()).isTrue(); + assertThat(excluded.matcher("/messages").matches()).isTrue(); + } + + @Test + void explicitExclusionsKeepTheirNormalPrecedence() { + var config = + config( + Map.of( + "quarkus.mcp.server.http.root-path", "/tools", + "quarkus.http.access-log.exclude-pattern", "/tools(/.*)?|/health")); + assertThat(config.getValue("quarkus.http.access-log.exclude-pattern", String.class)) + .isEqualTo("/tools(/.*)?|/health"); + } + + private SmallRyeConfig config(Map properties) { + return new SmallRyeConfigBuilder() + .withSources(new PropertiesConfigSource(properties, "test", 300)) + .withSources(new McpEndpointConfigSourceFactory()) + .build(); + } +} diff --git a/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingFilterTest.java b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingFilterTest.java new file mode 100644 index 0000000000..41314cc691 --- /dev/null +++ b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingFilterTest.java @@ -0,0 +1,146 @@ +package io.stargate.sgv2.jsonapi.api.v1.mcp; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatIllegalArgumentException; +import static org.mockito.Mockito.mock; +import static org.mockito.Mockito.when; + +import java.time.Clock; +import java.time.Instant; +import java.util.Map; +import java.util.Optional; +import java.util.logging.Level; +import org.jboss.logmanager.ExtLogRecord; +import org.junit.jupiter.api.Test; + +class McpLoggingFilterTest { + private static final Instant NOW = Instant.parse("2026-10-19T12:00:00Z"); + private static final String REQUEST_ID = "3480cda5-7ade-4f56-bc9f-d7d92407fb41"; + + @Test + void removesPayloadsFromMessagesParametersExceptionsAndContext() { + var filter = new McpLoggingFilter(Optional.empty()); + var record = sensitiveRecord("io.stargate.sgv2.jsonapi.service.processor.CommandProcessor"); + + assertThat(filter.isLoggable(record)).isTrue(); + assertThat(record.getFormattedMessage()) + .contains("exception=java.lang.IllegalArgumentException") + .doesNotContain("synthetic-"); + assertThat(record.getParameters()).isNull(); + assertThat(record.getThrown()).isNull(); + assertThat(record.getMdcCopy()) + .containsExactlyInAnyOrderEntriesOf( + Map.of( + McpRequestLogging.REQUEST_ID, + REQUEST_ID, + McpLoggingFilter.EXCEPTION_TYPE, + IllegalArgumentException.class.getName())); + assertThat(record.getNdc()).isEmpty(); + assertThat(record.getMarker()).isNull(); + assertThat(record.getLevel()).isEqualTo(Level.WARNING); + } + + @Test + void protectsFrameworkFailuresWithoutARequestContext() { + var record = + sensitiveRecord("io.quarkiverse.mcp.server.http.runtime.StreamableHttpMcpMessageHandler"); + record.setMdc(Map.of()); + assertThat(new McpLoggingFilter(Optional.empty()).isLoggable(record)).isTrue(); + assertThat(record.getFormattedMessage()).doesNotContain("synthetic-"); + assertThat(record.getThrown()).isNull(); + } + + @Test + void dropsRawTrafficEvenWhenDiagnosticsAreEnabled() { + Clock clock = mock(Clock.class); + when(clock.instant()).thenReturn(NOW); + var filter = new McpLoggingFilter(Optional.of(NOW.plusSeconds(60).toString()), clock); + assertThat(filter.isLoggable(sensitiveRecord("io.quarkus.mcp.server.traffic"))).isFalse(); + } + + @Test + void preservesExceptionTypeAcrossMultipleHandlers() { + Clock clock = mock(Clock.class); + when(clock.instant()).thenReturn(NOW); + for (var deadline : + java.util.List.of(Optional.empty(), Optional.of(NOW.plusSeconds(60).toString()))) { + var record = sensitiveRecord("io.stargate.command"); + var firstHandler = new McpLoggingFilter(deadline, clock); + var secondHandler = new McpLoggingFilter(deadline, clock); + + assertThat(firstHandler.isLoggable(record)).isTrue(); + assertThat(secondHandler.isLoggable(record)).isTrue(); + assertThat(record.getFormattedMessage()) + .contains("exception=java.lang.IllegalArgumentException") + .doesNotContain("synthetic-"); + } + } + + @Test + void diagnosticsKeepOnlyBoundedStackLocationsAndExpire() { + Clock clock = mock(Clock.class); + when(clock.instant()).thenReturn(NOW); + var filter = new McpLoggingFilter(Optional.of(NOW.plusSeconds(60).toString()), clock); + var record = sensitiveRecord("io.stargate.command"); + StackTraceElement frame = new StackTraceElement("example.Command", "run", "Command.java", 42); + record + .getThrown() + .setStackTrace(java.util.Collections.nCopies(40, frame).toArray(StackTraceElement[]::new)); + + assertThat(filter.isLoggable(record)).isTrue(); + assertThat(record.getThrown().getMessage()).doesNotContain("synthetic-"); + assertThat(record.getThrown().getCause()).isNull(); + assertThat(record.getThrown().getSuppressed()).isEmpty(); + assertThat(record.getThrown().getStackTrace()).hasSize(32).containsOnly(frame); + + when(clock.instant()).thenReturn(NOW.plusSeconds(60)); + var expired = sensitiveRecord("io.stargate.command"); + assertThat(filter.isLoggable(expired)).isTrue(); + assertThat(expired.getThrown()).isNull(); + } + + @Test + void rejectsUnboundedOrMalformedDiagnosticConfigurationWithoutEchoingIt() { + Clock clock = mock(Clock.class); + when(clock.instant()).thenReturn(NOW); + assertThatIllegalArgumentException() + .isThrownBy(() -> new McpLoggingFilter(Optional.of(NOW.plusSeconds(901).toString()), clock)) + .withMessageContaining("at most 15 minutes"); + assertThatIllegalArgumentException() + .isThrownBy(() -> new McpLoggingFilter(Optional.of("synthetic-config-secret"), clock)) + .withMessage("MCP diagnostics-until must be an ISO-8601 timestamp") + .withNoCause(); + } + + @Test + void leavesOrdinaryHttpAndBillingRecordsUnchanged() { + var filter = new McpLoggingFilter(Optional.empty()); + var http = sensitiveRecord("io.stargate.http"); + http.setMdc(Map.of()); + var billing = sensitiveRecord("billing.events"); + for (var record : java.util.List.of(http, billing)) { + String message = record.getMessage(); + Throwable failure = record.getThrown(); + assertThat(filter.isLoggable(record)).isTrue(); + assertThat(record.getMessage()).isEqualTo(message); + assertThat(record.getThrown()).isSameAs(failure); + } + } + + private ExtLogRecord sensitiveRecord(String logger) { + var record = + new ExtLogRecord(Level.WARNING, "synthetic-message-secret %s", getClass().getName()); + record.setLoggerName(logger); + record.setParameters(new Object[] {Map.of("access_token", "synthetic-parameter-secret")}); + var failure = + new IllegalArgumentException( + "synthetic-exception-secret", new RuntimeException("synthetic-cause-secret")); + failure.addSuppressed(new IllegalStateException("synthetic-suppressed-secret")); + record.setThrown(failure); + record.setMdc( + Map.of(McpRequestLogging.REQUEST_ID, REQUEST_ID, "tenantId", "synthetic-tenant-secret")); + record.setNdc("synthetic-ndc-secret"); + record.setMarker("synthetic-marker-secret"); + return record; + } +} diff --git a/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingIntegrationTest.java b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingIntegrationTest.java new file mode 100644 index 0000000000..1f6059d076 --- /dev/null +++ b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingIntegrationTest.java @@ -0,0 +1,94 @@ +package io.stargate.sgv2.jsonapi.api.v1.mcp; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.awaitility.Awaitility.await; + +import io.quarkus.test.common.WithTestResource; +import io.quarkus.test.junit.QuarkusIntegrationTest; +import io.quarkus.test.junit.QuarkusTestProfile; +import io.quarkus.test.junit.TestProfile; +import io.stargate.sgv2.jsonapi.testresource.DseTestResource; +import io.vertx.core.MultiMap; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; +import java.time.Duration; +import java.util.Arrays; +import java.util.List; +import java.util.Map; +import java.util.regex.Pattern; +import org.junit.jupiter.api.Test; + +/** Exercises log redaction through real driver callbacks in the packaged application. */ +@QuarkusIntegrationTest +@WithTestResource(DseTestResource.class) +@TestProfile(McpLoggingIntegrationTest.LoggingProfile.class) +class McpLoggingIntegrationTest extends McpIntegrationTestBase { + private static final Path LOG_FILE = + Path.of("target/mcp-packaged-logging-test.log").toAbsolutePath(); + private static final String PRIVATE_FIELD = "synthetic_private_index_field"; + + @Override + protected MultiMap authHeaders() { + return super.authHeaders().add("User-Agent", "synthetic_private_user_agent"); + } + + @Test + void collectionMetadataStaysRedactedAcrossDriverCallbacks() throws Exception { + createKeyspace(keyspaceName); + try { + long start = Files.size(LOG_FILE); + createCollection( + keyspaceName, + collectionName, + Map.of("indexing", Map.of("allow", List.of(PRIVATE_FIELD)))); + + await() + .atMost(Duration.ofSeconds(5)) + .untilAsserted( + () -> { + byte[] bytes = Files.readAllBytes(LOG_FILE); + String logs = + new String( + Arrays.copyOfRange(bytes, Math.toIntExact(start), bytes.length), + StandardCharsets.UTF_8); + var requestId = + Pattern.compile( + "MCP command completed requestId=([a-f0-9-]+) command=createCollection isError=false") + .matcher(logs); + assertThat(requestId.find()).as("The command has a generated request ID").isTrue(); + assertThat(logs.contains("MCP request completed requestId=" + requestId.group(1))) + .as("Command and HTTP completion share the request ID") + .isTrue(); + assertThat( + logs.lines() + .anyMatch( + line -> + line.contains("CreateCollectionOperation") + && line.contains("MCP event details redacted"))) + .as("Collection metadata logging is active and redacted") + .isTrue(); + assertThat(logs.contains(PRIVATE_FIELD)) + .as("Private collection metadata stays out of logs") + .isFalse(); + assertThat(logs.contains("synthetic_private_user_agent")) + .as("Request cache metadata stays out of logs") + .isFalse(); + assertThat(logs.contains("requestId=null")).isFalse(); + }); + } finally { + dropKeyspace(keyspaceName); + } + } + + public static class LoggingProfile implements QuarkusTestProfile { + @Override + public Map getConfigOverrides() { + return Map.of( + "quarkus.log.file.enabled", "true", + "quarkus.log.file.path", LOG_FILE.toString(), + "quarkus.log.category.\"io.stargate.sgv2.jsonapi.service.operation.collections.CreateCollectionOperation\".level", + "DEBUG"); + } + } +} diff --git a/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingTest.java b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingTest.java new file mode 100644 index 0000000000..958b349720 --- /dev/null +++ b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpLoggingTest.java @@ -0,0 +1,304 @@ +package io.stargate.sgv2.jsonapi.api.v1.mcp; + +import static io.restassured.RestAssured.given; +import static io.stargate.sgv2.jsonapi.api.v1.mcp.McpHttpTestSupport.assertResponseComplete; +import static org.assertj.core.api.Assertions.assertThat; +import static org.awaitility.Awaitility.await; +import static org.mockito.ArgumentMatchers.any; +import static org.mockito.Mockito.when; + +import com.fasterxml.jackson.databind.node.JsonNodeFactory; +import io.quarkus.test.InjectMock; +import io.quarkus.test.junit.QuarkusTest; +import io.quarkus.test.junit.TestProfile; +import io.restassured.http.ContentType; +import io.smallrye.mutiny.Uni; +import io.stargate.sgv2.jsonapi.api.model.command.CommandContext; +import io.stargate.sgv2.jsonapi.api.model.command.CommandResult; +import io.stargate.sgv2.jsonapi.api.model.command.tracing.RequestTracing; +import io.stargate.sgv2.jsonapi.config.feature.ApiFeature; +import io.stargate.sgv2.jsonapi.service.processor.CommandProcessor; +import io.stargate.sgv2.jsonapi.testresource.NoGlobalResourcesTestProfile; +import io.vertx.core.json.JsonObject; +import java.io.IOException; +import java.nio.charset.StandardCharsets; +import java.nio.file.Files; +import java.nio.file.Path; +import java.time.Duration; +import java.util.Arrays; +import java.util.Map; +import java.util.concurrent.CompletableFuture; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; +import java.util.regex.Pattern; +import org.eclipse.microprofile.config.ConfigProvider; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; +import org.slf4j.MDC; + +@QuarkusTest +@TestProfile(McpLoggingTest.LoggingProfile.class) +class McpLoggingTest { + static final Path LOG_FILE = Path.of("target/mcp-logging-test.log"); + @InjectMock CommandProcessor commandProcessor; + + @Test + void normalLogsExcludePayloadsAndCredentials() throws IOException { + long start = Files.size(LOG_FILE); + given() + .contentType(ContentType.JSON) + .accept("application/json, text/event-stream") + .header("Token", "synthetic-header-secret") + .header("Authorization", "Bearer synthetic-access-secret") + .header("MCP-Protocol-Version", "2026-07-28") + .header("Mcp-Method", "tools/list") + .body( + Map.of( + "jsonrpc", "2.0", + "id", "synthetic-rpc-id-secret", + "method", "tools/list", + "params", + Map.of( + "_meta", + Map.of( + "io.modelcontextprotocol/protocolVersion", "2026-07-28", + "io.modelcontextprotocol/clientCapabilities", Map.of(), + "document", "synthetic-document-secret", + "query", "synthetic-query-secret", + "refresh_token", "synthetic-refresh-secret", + "code_verifier", "synthetic-pkce-secret", + "client_secret", "synthetic-registration-secret")))) + .post(mcpPath() + "?code=synthetic-code-secret") + .then() + .statusCode(200); + + assertThat(logsSince(start)) + .contains("MCP request completed", "method=tools/list", "status=200") + .doesNotContain("synthetic-"); + } + + @Test + void errorLogsExcludeMalformedHeadersAndBodies() throws IOException { + long start = Files.size(LOG_FILE); + given() + .contentType(ContentType.JSON) + .accept("synthetic-invalid-accept-secret") + .header("Token", "synthetic-header-secret") + .body("{}") + .post(mcpPath()) + .then() + .statusCode(400); + given() + .contentType(ContentType.JSON) + .accept("application/json, text/event-stream") + .header("Token", "synthetic-header-secret") + .body("{\"access_token\":synthetic-malformed-body-secret}") + .post(mcpPath()); + + assertThat(logsSince(start)) + .contains("MCP event details redacted", "status=400") + .doesNotContain("synthetic-"); + } + + @Test + void returnedDocumentsStayOutOfLogsButCommandCategoriesRemain() throws IOException { + var result = + CommandResult.singleDocumentBuilder(RequestTracing.NO_OP) + .addDocument( + JsonNodeFactory.instance.objectNode().put("document", "synthetic-response-secret")) + .build(); + when(commandProcessor.processCommand(any(), any())).thenReturn(Uni.createFrom().item(result)); + long start = Files.size(LOG_FILE); + + callProviderTool(); + + assertThat(logsSince(start)) + .contains( + "MCP command completed", + "command=findEmbeddingProviders", + "isError=false", + "requestId=") + .doesNotContain("synthetic-"); + } + + @Test + void diagnosticTraceAndCompletionLogsShareAGeneratedRequestId() throws IOException { + when(commandProcessor.processCommand(any(), any())) + .thenAnswer( + invocation -> { + CommandContext context = invocation.getArgument(0); + return Uni.createFrom() + .item(CommandResult.statusOnlyBuilder(context.requestTracing()).build()); + }); + var clientRequestId = "11111111-1111-4111-8111-111111111111"; + var payload = + new JsonObject(McpHttpTestSupport.toolPayload(1, "findEmbeddingProviders", Map.of())) + .copy(); + payload + .getJsonObject("params") + .getJsonObject("_meta") + .put("requestId", clientRequestId) + .put("mcpRequestId", clientRequestId); + long start = Files.size(LOG_FILE); + + var response = + McpHttpTestSupport.request("tools/call") + .header("Token", "synthetic-header-secret") + .header("Mcp-Name", "findEmbeddingProviders") + .header(ApiFeature.REQUEST_TRACING.httpHeaderName(), "true") + .header("X-Request-ID", clientRequestId) + .header("mcpRequestId", clientRequestId) + .body(payload.encode()) + .post(mcpPath()); + + var requestId = + assertResponseComplete(response, 1) + .getJsonObject("_meta") + .getJsonObject("status") + .getJsonObject("trace") + .getJsonObject("TraceSession") + .getString("requestId"); + assertThat(requestId).matches("[a-f0-9-]{36}").isNotEqualTo(clientRequestId); + assertThat(logsSince(start)) + .contains( + "MCP request completed requestId=" + requestId, + "MCP command completed requestId=" + + requestId + + " command=findEmbeddingProviders isError=false") + .doesNotContain(clientRequestId); + } + + @Test + void asynchronousCommandErrorsStayOutOfLogs() throws IOException { + when(commandProcessor.processCommand(any(), any())) + .thenAnswer( + invocation -> + Uni.createFrom() + .item(1) + .onItem() + .delayIt() + .by(Duration.ofMillis(1)) + .map( + ignored -> + CommandResult.statusOnlyBuilder(RequestTracing.NO_OP) + .addThrowable( + new IllegalArgumentException("synthetic-command-error-secret")) + .build())); + long start = Files.size(LOG_FILE); + + callProviderTool(); + + assertThat(logsSince(start)) + .contains("MCP command completed", "command=findEmbeddingProviders", "isError=true") + .doesNotContain("synthetic-"); + } + + @Test + void asynchronousCommandFailuresStayOutOfLogs() throws IOException { + when(commandProcessor.processCommand(any(), any())) + .thenAnswer( + invocation -> + Uni.createFrom() + .item(1) + .onItem() + .delayIt() + .by(Duration.ofMillis(1)) + .map( + ignored -> { + throw new IllegalStateException("synthetic-command-failure-secret"); + })); + long start = Files.size(LOG_FILE); + + callProviderTool(); + + assertThat(logsSince(start)) + .contains("MCP command failed", "command=findEmbeddingProviders") + .doesNotContain("synthetic-"); + } + + @Test + void driverThreadCallbacksKeepRequestIdAndRestoreWorkerContext() throws Exception { + try (var worker = Executors.newSingleThreadExecutor()) { + // Start the worker before a request can contribute inherited context. + assertThat(worker.submit(() -> MDC.get(McpRequestLogging.REQUEST_ID)).get()).isNull(); + var completed = new CompletableFuture(); + when(commandProcessor.processCommand(any(), any())) + .thenAnswer( + ignored -> + Uni.createFrom() + .completionStage(completed) + .map( + value -> { + LoggerFactory.getLogger(McpLoggingTest.class) + .info("synthetic-driver-payload-secret"); + return CommandResult.statusOnlyBuilder(RequestTracing.NO_OP).build(); + })); + var completion = + worker.submit( + () -> { + await() + .atMost(Duration.ofSeconds(10)) + .until(() -> completed.getNumberOfDependents() > 0); + completed.complete(1); + return MDC.get(McpRequestLogging.REQUEST_ID); + }); + long start = Files.size(LOG_FILE); + + callProviderTool(); + + assertThat(completion.get(10, TimeUnit.SECONDS)).isNull(); + String logs = logsSince(start); + var requestId = Pattern.compile("MCP request completed requestId=([a-f0-9-]+)").matcher(logs); + assertThat(requestId.find()).isTrue(); + assertThat(logs.contains("MCP event details redacted")).isTrue(); + assertThat(logs.contains("MCP command completed requestId=" + requestId.group(1))).isTrue(); + assertThat(logs.contains("synthetic-")).as("Payloads stay out of logs").isFalse(); + assertThat(logs.contains("requestId=null")).isFalse(); + } + } + + private void callProviderTool() { + McpHttpTestSupport.request("tools/call") + .header("Token", "synthetic-header-secret") + .header("Mcp-Name", "findEmbeddingProviders") + .body(McpHttpTestSupport.toolPayload(1, "findEmbeddingProviders", Map.of())) + .post(mcpPath()) + .then() + .statusCode(200); + } + + static String logsSince(long start) throws IOException { + byte[] bytes = Files.readAllBytes(LOG_FILE); + return new String( + Arrays.copyOfRange(bytes, Math.toIntExact(start), bytes.length), StandardCharsets.UTF_8); + } + + @Test + void subsequentHttpRequestsKeepTheirOrdinaryLogs() throws IOException { + normalLogsExcludePayloadsAndCredentials(); + long start = Files.size(LOG_FILE); + assertThat(given().get("/v1/logging-isolation-check").statusCode()).isIn(401, 404); + await() + .atMost(Duration.ofSeconds(5)) + .untilAsserted( + () -> assertThat(logsSince(start)).contains("/v1/logging-isolation-check HTTP/1.1")); + } + + private String mcpPath() { + // RestAssured's base path already includes quarkus.http.root-path. + return ConfigProvider.getConfig().getValue("quarkus.mcp.server.http.root-path", String.class); + } + + public static class LoggingProfile implements NoGlobalResourcesTestProfile { + @Override + public Map getConfigOverrides() { + return Map.of( + "quarkus.log.file.enabled", "true", + "quarkus.log.file.path", LOG_FILE.toString(), + "quarkus.log.file.format", "%p %c %m%e%n", + "stargate.feature.flags.mcp", "true", + "quarkus.http.access-log.enabled", "true", + "quarkus.log.category.\"io.quarkus.mcp.server.traffic\".level", "INFO"); + } + } +} diff --git a/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpRequestContextProviderTest.java b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpRequestContextProviderTest.java new file mode 100644 index 0000000000..c80df15550 --- /dev/null +++ b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpRequestContextProviderTest.java @@ -0,0 +1,162 @@ +package io.stargate.sgv2.jsonapi.api.v1.mcp; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatThrownBy; + +import java.util.Map; +import java.util.concurrent.ExecutionException; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.ValueSource; +import org.slf4j.MDC; + +class McpRequestContextProviderTest { + private final McpRequestContextProvider provider = new McpRequestContextProvider(); + + @AfterEach + void clearContext() { + MDC.remove(McpRequestLogging.REQUEST_ID); + MDC.remove("unrelated"); + } + + @Test + void capturesAtSnapshotCreationAndRestoresNestedContexts() { + MDC.put(McpRequestLogging.REQUEST_ID, "outer"); + var outer = provider.currentContext(Map.of()); + MDC.put(McpRequestLogging.REQUEST_ID, "inner"); + var inner = provider.currentContext(Map.of()); + MDC.put(McpRequestLogging.REQUEST_ID, "previous"); + + var outerScope = outer.begin(); + try { + assertThat(MDC.get(McpRequestLogging.REQUEST_ID)).isEqualTo("outer"); + var innerScope = inner.begin(); + try { + assertThat(MDC.get(McpRequestLogging.REQUEST_ID)).isEqualTo("inner"); + } finally { + innerScope.endContext(); + } + assertThat(MDC.get(McpRequestLogging.REQUEST_ID)).isEqualTo("outer"); + } finally { + outerScope.endContext(); + } + assertThat(MDC.get(McpRequestLogging.REQUEST_ID)).isEqualTo("previous"); + } + + @Test + void anAbsentCapturedContextClearsAndRestoresTheCurrentMarker() { + MDC.remove(McpRequestLogging.REQUEST_ID); + var snapshot = provider.currentContext(Map.of()); + MDC.put(McpRequestLogging.REQUEST_ID, "previous"); + + var scope = snapshot.begin(); + try { + assertThat(MDC.get(McpRequestLogging.REQUEST_ID)).isNull(); + } finally { + scope.endContext(); + } + assertThat(MDC.get(McpRequestLogging.REQUEST_ID)).isEqualTo("previous"); + } + + @Test + void clearedContextIgnoresTheCapturedMarker() { + MDC.put(McpRequestLogging.REQUEST_ID, "captured"); + var snapshot = provider.clearedContext(Map.of()); + MDC.put(McpRequestLogging.REQUEST_ID, "previous"); + + var scope = snapshot.begin(); + try { + assertThat(MDC.get(McpRequestLogging.REQUEST_ID)).isNull(); + } finally { + scope.endContext(); + } + assertThat(MDC.get(McpRequestLogging.REQUEST_ID)).isEqualTo("previous"); + } + + @Test + void restoresAnAbsentMarker() { + MDC.put(McpRequestLogging.REQUEST_ID, "captured"); + var snapshot = provider.currentContext(Map.of()); + MDC.remove(McpRequestLogging.REQUEST_ID); + + var scope = snapshot.begin(); + try { + assertThat(MDC.get(McpRequestLogging.REQUEST_ID)).isEqualTo("captured"); + } finally { + scope.endContext(); + } + assertThat(MDC.get(McpRequestLogging.REQUEST_ID)).isNull(); + } + + @Test + void leavesOtherMdcEntriesAlone() { + MDC.put(McpRequestLogging.REQUEST_ID, "captured"); + MDC.put("unrelated", "source"); + var snapshot = provider.currentContext(Map.of()); + MDC.put("unrelated", "worker"); + + var scope = snapshot.begin(); + try { + assertThat(MDC.get("unrelated")).isEqualTo("worker"); + MDC.put("unrelated", "changed"); + } finally { + scope.endContext(); + } + assertThat(MDC.get("unrelated")).isEqualTo("changed"); + } + + @ParameterizedTest + @ValueSource(booleans = {false, true}) + void reusingAWorkerRestoresItsContextAfterSuccessAndFailure(boolean fail) throws Exception { + try (var worker = Executors.newSingleThreadExecutor()) { + worker + .submit(() -> MDC.put(McpRequestLogging.REQUEST_ID, "worker")) + .get(10, TimeUnit.SECONDS); + MDC.put(McpRequestLogging.REQUEST_ID, "first-request"); + var first = provider.currentContext(Map.of()); + var result = + worker.submit( + () -> { + var scope = first.begin(); + try { + assertThat(MDC.get(McpRequestLogging.REQUEST_ID)).isEqualTo("first-request"); + if (fail) { + throw new IllegalStateException("expected failure"); + } + } finally { + scope.endContext(); + } + }); + if (fail) { + assertThatThrownBy(() -> result.get(10, TimeUnit.SECONDS)) + .isInstanceOf(ExecutionException.class) + .hasCauseInstanceOf(IllegalStateException.class); + } else { + result.get(10, TimeUnit.SECONDS); + } + assertThat( + worker.submit(() -> MDC.get(McpRequestLogging.REQUEST_ID)).get(10, TimeUnit.SECONDS)) + .isEqualTo("worker"); + + MDC.put(McpRequestLogging.REQUEST_ID, "second-request"); + var second = provider.currentContext(Map.of()); + worker + .submit( + () -> { + var scope = second.begin(); + try { + assertThat(MDC.get(McpRequestLogging.REQUEST_ID)).isEqualTo("second-request"); + } finally { + scope.endContext(); + } + }) + .get(10, TimeUnit.SECONDS); + assertThat( + worker.submit(() -> MDC.get(McpRequestLogging.REQUEST_ID)).get(10, TimeUnit.SECONDS)) + .isEqualTo("worker"); + } + } +} diff --git a/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpResourceTest.java b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpResourceTest.java index f4d603f45e..ff95fde389 100644 --- a/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpResourceTest.java +++ b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpResourceTest.java @@ -17,6 +17,7 @@ import io.smallrye.mutiny.Uni; import io.stargate.sgv2.jsonapi.TestConstants; import io.stargate.sgv2.jsonapi.api.model.command.CommandContext; +import io.stargate.sgv2.jsonapi.api.model.command.CommandName; import io.stargate.sgv2.jsonapi.api.model.command.CommandResult; import io.stargate.sgv2.jsonapi.api.model.command.KeyspaceCommand; import io.stargate.sgv2.jsonapi.api.model.command.tracing.RequestTracing; @@ -60,14 +61,14 @@ class McpResourceTest { @Test void closesContextOnSuccess() throws Exception { var context = commandContext(true); - var command = mock(KeyspaceCommand.class); + var command = keyspaceCommand(); var result = CommandResult.statusOnlyBuilder(RequestTracing.NO_OP).build(); when(commandProcessor.processCommand(context, command)) .thenReturn(Uni.createFrom().item(result)); var response = mcpResource() - .processCommand(Uni.createFrom().item(context), command) + .processCommand(() -> Uni.createFrom().item(context), command) .await() .atMost(Duration.ofSeconds(5)); @@ -78,14 +79,14 @@ void closesContextOnSuccess() throws Exception { @Test void closesContextOnFailure() throws Exception { var context = commandContext(true); - var command = mock(KeyspaceCommand.class); + var command = keyspaceCommand(); when(commandProcessor.processCommand(context, command)) .thenReturn(Uni.createFrom().failure(new RuntimeException("processor failed"))); assertThatThrownBy( () -> mcpResource() - .processCommand(Uni.createFrom().item(context), command) + .processCommand(() -> Uni.createFrom().item(context), command) .await() .atMost(Duration.ofSeconds(5))) .hasMessage("processor failed"); @@ -95,14 +96,14 @@ void closesContextOnFailure() throws Exception { @Test void closesContextWhenProcessorThrowsSynchronously() throws Exception { var context = commandContext(true); - var command = mock(KeyspaceCommand.class); + var command = keyspaceCommand(); var failure = new IllegalStateException("processor failed before returning a Uni"); when(commandProcessor.processCommand(context, command)).thenThrow(failure); assertThatThrownBy( () -> mcpResource() - .processCommand(Uni.createFrom().item(context), command) + .processCommand(() -> Uni.createFrom().item(context), command) .await() .atMost(Duration.ofSeconds(5))) .isSameAs(failure); @@ -118,7 +119,7 @@ void closesContextWhenFeatureConfigurationIsInvalid() throws Exception { assertThatThrownBy( () -> mcpResource() - .processCommand(Uni.createFrom().item(context), mock(KeyspaceCommand.class)) + .processCommand(() -> Uni.createFrom().item(context), keyspaceCommand()) .await() .atMost(Duration.ofSeconds(5))) .isInstanceOf(IllegalArgumentException.class); @@ -129,11 +130,11 @@ void closesContextWhenFeatureConfigurationIsInvalid() throws Exception { @Test void closesContextWhenFeatureDisabled() throws Exception { var context = commandContext(false); - var command = mock(KeyspaceCommand.class); + var command = keyspaceCommand(); var response = mcpResource() - .processCommand(Uni.createFrom().item(context), command) + .processCommand(() -> Uni.createFrom().item(context), command) .await() .atMost(Duration.ofSeconds(5)); @@ -145,13 +146,13 @@ void closesContextWhenFeatureDisabled() throws Exception { @Test void closesContextOnCancellation() throws Exception { var context = commandContext(true); - var command = mock(KeyspaceCommand.class); + var command = keyspaceCommand(); when(commandProcessor.processCommand(context, command)) .thenReturn(Uni.createFrom().emitter(emitter -> {})); var cancellable = mcpResource() - .processCommand(Uni.createFrom().item(context), command) + .processCommand(() -> Uni.createFrom().item(context), command) .subscribe() .with(response -> {}, failure -> {}); cancellable.cancel(); @@ -163,14 +164,14 @@ void closesContextOnCancellation() throws Exception { void closeFailureDoesNotReplaceResult() throws Exception { var context = commandContext(true); doThrow(new Exception("close failed")).when(context).close(); - var command = mock(KeyspaceCommand.class); + var command = keyspaceCommand(); var result = CommandResult.statusOnlyBuilder(RequestTracing.NO_OP).build(); when(commandProcessor.processCommand(context, command)) .thenReturn(Uni.createFrom().item(result)); var response = mcpResource() - .processCommand(Uni.createFrom().item(context), command) + .processCommand(() -> Uni.createFrom().item(context), command) .await() .atMost(Duration.ofSeconds(5)); @@ -182,14 +183,14 @@ void closeFailureDoesNotReplaceResult() throws Exception { void closeFailureDoesNotReplaceError() throws Exception { var context = commandContext(true); doThrow(new Exception("close failed")).when(context).close(); - var command = mock(KeyspaceCommand.class); + var command = keyspaceCommand(); when(commandProcessor.processCommand(context, command)) .thenReturn(Uni.createFrom().failure(new RuntimeException("processor failed"))); assertThatThrownBy( () -> mcpResource() - .processCommand(Uni.createFrom().item(context), command) + .processCommand(() -> Uni.createFrom().item(context), command) .await() .atMost(Duration.ofSeconds(5))) .hasMessage("processor failed"); @@ -204,7 +205,7 @@ void keyspaceContextUsesOneRequestContext() { var context = mcpResourceWithRequest() - .buildKeyspaceContext(TEST_CONSTANTS.KEYSPACE_NAME, mock(KeyspaceCommand.class)) + .buildKeyspaceContext(TEST_CONSTANTS.KEYSPACE_NAME, keyspaceCommand()) .await() .atMost(Duration.ofSeconds(5)); @@ -213,6 +214,12 @@ void keyspaceContextUsesOneRequestContext() { assertThat(context.requestContext()).isSameAs(requestContextCaptor.getValue()); } + private KeyspaceCommand keyspaceCommand() { + var command = mock(KeyspaceCommand.class); + when(command.commandName()).thenReturn(CommandName.FIND_COLLECTIONS); + return command; + } + @SuppressWarnings("unchecked") private CommandContext commandContext(boolean mcpEnabled) { CommandContext context = mock(CommandContext.class); diff --git a/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpSetupErrorsTest.java b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpSetupErrorsTest.java index 889e2e5038..17769f2470 100644 --- a/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpSetupErrorsTest.java +++ b/src/test/java/io/stargate/sgv2/jsonapi/api/v1/mcp/McpSetupErrorsTest.java @@ -36,12 +36,14 @@ import io.stargate.sgv2.jsonapi.TestConstants; import io.stargate.sgv2.jsonapi.api.model.command.CollectionCommand; import io.stargate.sgv2.jsonapi.api.model.command.CommandConfig; +import io.stargate.sgv2.jsonapi.api.model.command.CommandName; import io.stargate.sgv2.jsonapi.api.model.command.CommandResult; import io.stargate.sgv2.jsonapi.api.model.command.CommandStatus; import io.stargate.sgv2.jsonapi.api.model.command.GeneralCommand; import io.stargate.sgv2.jsonapi.api.model.command.KeyspaceCommand; import io.stargate.sgv2.jsonapi.api.model.command.tracing.RequestTracing; import io.stargate.sgv2.jsonapi.api.request.EmbeddingCredentialsResolver; +import io.stargate.sgv2.jsonapi.api.request.RequestContext; import io.stargate.sgv2.jsonapi.api.request.tenant.RequestTenantResolver; import io.stargate.sgv2.jsonapi.config.feature.ApiFeature; import io.stargate.sgv2.jsonapi.config.feature.FeaturesConfig; @@ -58,6 +60,7 @@ import io.stargate.sgv2.jsonapi.service.reranking.operation.RerankingProviderFactory; import io.stargate.sgv2.jsonapi.service.schema.SchemaObjectCache; import io.stargate.sgv2.jsonapi.service.schema.SchemaObjectCacheSupplier; +import io.stargate.sgv2.jsonapi.util.LoggerTestWrapper; import io.vertx.core.MultiMap; import io.vertx.core.http.HttpServerRequest; import io.vertx.ext.web.RoutingContext; @@ -65,6 +68,7 @@ import jakarta.ws.rs.WebApplicationException; import java.security.Principal; import java.time.Duration; +import java.util.HashMap; import java.util.Map; import java.util.concurrent.CancellationException; import java.util.concurrent.CompletionException; @@ -91,6 +95,7 @@ class McpSetupErrorsTest { private final EmbeddingProviderFactory embeddingProviderFactory = mock(EmbeddingProviderFactory.class); private final RequestTenantResolver tenantResolver = mock(RequestTenantResolver.class); + private final RoutingContext routingContext = mock(RoutingContext.class); private final GeneralCommand generalCommand = mock(GeneralCommand.class); private final KeyspaceCommand keyspaceCommand = mock(KeyspaceCommand.class); private final CollectionCommand collectionCommand = mock(CollectionCommand.class); @@ -99,6 +104,9 @@ class McpSetupErrorsTest { @BeforeEach void setUp() { + when(generalCommand.commandName()).thenReturn(CommandName.FIND_EMBEDDING_PROVIDERS); + when(keyspaceCommand.commandName()).thenReturn(CommandName.FIND_COLLECTIONS); + when(collectionCommand.commandName()).thenReturn(CommandName.COUNT_DOCUMENTS); // Supply only application configuration. MCP enablement still comes from real request headers. var commandConfig = mock(CommandConfig.class); when(commandConfig.get(FeaturesConfig.class)).thenReturn(() -> Map.of()); @@ -108,7 +116,15 @@ void setUp() { var headers = MultiMap.caseInsensitiveMultiMap().add(ApiFeature.MCP.httpHeaderName(), "true"); var httpRequest = mock(HttpServerRequest.class); when(httpRequest.headers()).thenReturn(headers); - var routingContext = mock(RoutingContext.class); + var routingData = new HashMap(); + when(routingContext.get(anyString())) + .thenAnswer(invocation -> routingData.get(invocation.getArgument(0))); + when(routingContext.put(anyString(), any())) + .thenAnswer( + invocation -> { + routingData.put(invocation.getArgument(0), invocation.getArgument(1)); + return routingContext; + }); when(routingContext.request()).thenReturn(httpRequest); var principal = mock(Principal.class); when(principal.getName()).thenReturn("test-token"); @@ -164,7 +180,7 @@ void nullKeyspaceIdentifierBecomesADeferredToolError() throws Exception { assertDoesNotThrow( () -> resource.processCommand( - resource.buildKeyspaceContext(null, keyspaceCommand), keyspaceCommand)); + () -> resource.buildKeyspaceContext(null, keyspaceCommand), keyspaceCommand)); verifyNoInteractions(tenantResolver, schemaObjectCache, commandProcessor); assertSetupError(response, ServerException.Code.UNEXPECTED_SERVER_ERROR.name()); @@ -261,6 +277,29 @@ void unknownSetupFailureDoesNotExposeExceptionDetails() throws Exception { assertThat(error.toString()).doesNotContain(SECRET, IllegalStateException.class.getName()); } + @Test + void unexpectedSetupFailureRecordsASafeDiagnostic() throws Exception { + when(schemaObjectCache.getTableBased(any(), any(), any(), anyBoolean())) + .thenReturn(Uni.createFrom().failure(new IllegalStateException(SECRET))); + var requestId = RequestContext.getOrCreateRequestId(routingContext); + + try (var logs = new LoggerTestWrapper(McpRequestLogging.class)) { + assertSetupError( + call(CommandScope.COLLECTION), ServerException.Code.UNEXPECTED_SERVER_ERROR.name()); + assertThat(logs.logRecords()) + .filteredOn(record -> record.getMessage().contains("MCP setup failed")) + .singleElement() + .satisfies( + record -> { + assertThat(record.getMessage()) + .contains("category=unexpected") + .doesNotContain(SECRET); + assertThat(record.getParameters()).containsExactly(requestId); + assertThat(record.getThrown()).isNull(); + }); + } + } + @Test void completionWrappedSetupErrorRetainsItsActionableMessage() throws Exception { var failure = SchemaException.Code.UNKNOWN_KEYSPACE.get("keyspace", "missing-keyspace"); @@ -375,10 +414,11 @@ private void assertNextKeyspaceCallSucceeds() { private Uni call(CommandScope scope) { return switch (scope) { case DATABASE -> - resource.processCommand(resource.buildDatabaseContext(generalCommand), generalCommand); + resource.processCommand( + () -> resource.buildDatabaseContext(generalCommand), generalCommand); case KEYSPACE -> resource.processCommand( - resource.buildKeyspaceContext(TEST_CONSTANTS.KEYSPACE_NAME, keyspaceCommand), + () -> resource.buildKeyspaceContext(TEST_CONSTANTS.KEYSPACE_NAME, keyspaceCommand), keyspaceCommand); case COLLECTION -> resource.processCollectionCommand(