feat: Refine logging levels (#985)
The logging is sometimes too verbose and uses inappropriate level. With this change there should be less disturbing logs and less duplication. Notable changes: * `LifeCycleInitializer#handleException` - duplicated log, already handled in transports that use the initializer. * `McpClientSession#sendRequest` - an MCP protocol level error in JSON-RPC is not really a reason for ERROR level log. Using INFO with more details. * `DefaultJsonSchemaValidator` - ERROR logs in `validate` are always logged by the users of this method. `validateSchema` surfaces as `IllegalArgumentException` and can be logged at higher levels by the user. Also: remove DEBUG logs from mcp-test module. Signed-off-by: Dariusz Jędrzejczyk <2554306+chemicL@users.noreply.github.com>
This commit is contained in:
parent
c6d365c418
commit
c8ab3411b9
11 changed files with 70 additions and 33 deletions
|
|
@ -250,7 +250,6 @@ class LifecycleInitializer {
|
|||
* @param t The exception to handle
|
||||
*/
|
||||
public void handleException(Throwable t) {
|
||||
logger.warn("Handling exception", t);
|
||||
if (t instanceof McpTransportSessionNotFoundException) {
|
||||
DefaultInitialization previous = this.initializationRef.getAndSet(null);
|
||||
if (previous != null) {
|
||||
|
|
|
|||
|
|
@ -484,9 +484,7 @@ public class McpAsyncClient {
|
|||
if (this.isInitialized()) {
|
||||
return this.rootsListChangedNotification();
|
||||
}
|
||||
else {
|
||||
logger.warn("Client is not initialized, ignore sending a roots list changed notification");
|
||||
}
|
||||
logger.debug("Client is not initialized, ignore sending a roots list changed notification");
|
||||
}
|
||||
return Mono.empty();
|
||||
}
|
||||
|
|
@ -514,10 +512,7 @@ public class McpAsyncClient {
|
|||
if (this.isInitialized()) {
|
||||
return this.rootsListChangedNotification();
|
||||
}
|
||||
else {
|
||||
logger.warn("Client is not initialized, ignore sending a roots list changed notification");
|
||||
}
|
||||
|
||||
logger.debug("Client is not initialized, ignore sending a roots list changed notification");
|
||||
}
|
||||
return Mono.empty();
|
||||
}
|
||||
|
|
|
|||
|
|
@ -10,10 +10,13 @@ import java.io.InputStreamReader;
|
|||
import java.nio.charset.StandardCharsets;
|
||||
import java.time.Duration;
|
||||
import java.util.ArrayList;
|
||||
import java.util.EnumSet;
|
||||
import java.util.List;
|
||||
import java.util.Set;
|
||||
import java.util.concurrent.Executors;
|
||||
import java.util.function.Consumer;
|
||||
import java.util.function.Function;
|
||||
import java.util.stream.IntStream;
|
||||
|
||||
import io.modelcontextprotocol.json.TypeRef;
|
||||
import io.modelcontextprotocol.json.McpJsonMapper;
|
||||
|
|
@ -41,6 +44,15 @@ public class StdioClientTransport implements McpClientTransport {
|
|||
|
||||
private static final Logger logger = LoggerFactory.getLogger(StdioClientTransport.class);
|
||||
|
||||
// @formatter:off
|
||||
private static final Set<Integer> EXIT_SUCCESS_CODES = Set.of(
|
||||
0, // success
|
||||
130, // interrupted (SIGINT)
|
||||
141, // pipeline shortcut (SIGPIPE)
|
||||
143 // graceful termination (SIGTERM)
|
||||
);
|
||||
// @formatter:on
|
||||
|
||||
private final Sinks.Many<JSONRPCMessage> inboundSink;
|
||||
|
||||
private final Sinks.Many<JSONRPCMessage> outboundSink;
|
||||
|
|
@ -356,11 +368,12 @@ public class StdioClientTransport implements McpClientTransport {
|
|||
return Mono.<Process>empty();
|
||||
}
|
||||
})).doOnNext(process -> {
|
||||
if (process.exitValue() != 0) {
|
||||
logger.warn("Process terminated with code {}", process.exitValue());
|
||||
int exitValue = process.exitValue();
|
||||
if (EXIT_SUCCESS_CODES.contains(exitValue)) {
|
||||
logger.info("MCP server completed successfully with code {}", exitValue);
|
||||
}
|
||||
else {
|
||||
logger.info("MCP server process stopped");
|
||||
logger.warn("MCP server process failed with code {}", exitValue);
|
||||
}
|
||||
}).then(Mono.fromRunnable(() -> {
|
||||
try {
|
||||
|
|
|
|||
|
|
@ -513,14 +513,13 @@ public class McpAsyncServer {
|
|||
|
||||
return Mono.defer(() -> {
|
||||
if (this.tools.removeIf(toolSpecification -> toolSpecification.tool().name().equals(toolName))) {
|
||||
|
||||
logger.debug("Removed tool handler: {}", toolName);
|
||||
if (this.serverCapabilities.tools().listChanged()) {
|
||||
return notifyToolsListChanged();
|
||||
}
|
||||
}
|
||||
else {
|
||||
logger.warn("Ignore as a Tool with name '{}' not found", toolName);
|
||||
logger.warn("Failed to remove tool with name '{}' (not found)", toolName);
|
||||
}
|
||||
|
||||
return Mono.empty();
|
||||
|
|
@ -637,7 +636,7 @@ public class McpAsyncServer {
|
|||
return Mono.empty();
|
||||
}
|
||||
else {
|
||||
logger.warn("Ignore as a Resource with URI '{}' not found", resourceUri);
|
||||
logger.warn("Failed to remove resource with URI '{}' (not found)", resourceUri);
|
||||
}
|
||||
return Mono.empty();
|
||||
});
|
||||
|
|
@ -701,7 +700,7 @@ public class McpAsyncServer {
|
|||
logger.debug("Removed resource template: {}", uriTemplate);
|
||||
}
|
||||
else {
|
||||
logger.warn("Ignore as a Resource Template with URI '{}' not found", uriTemplate);
|
||||
logger.warn("Failed to remove a resource template with URI '{}' (not found)", uriTemplate);
|
||||
}
|
||||
return Mono.empty();
|
||||
});
|
||||
|
|
@ -907,7 +906,7 @@ public class McpAsyncServer {
|
|||
return Mono.empty();
|
||||
}
|
||||
else {
|
||||
logger.warn("Ignore as a Prompt with name '{}' not found", promptName);
|
||||
logger.warn("Failed to remove a prompt with name '{}' (not found)", promptName);
|
||||
}
|
||||
return Mono.empty();
|
||||
});
|
||||
|
|
|
|||
|
|
@ -390,7 +390,7 @@ public class McpStatelessAsyncServer {
|
|||
logger.debug("Removed tool handler: {}", toolName);
|
||||
}
|
||||
else {
|
||||
logger.warn("Ignore as a Tool with name '{}' not found", toolName);
|
||||
logger.warn("Failed to remove a tool with name '{}' (not found)", toolName);
|
||||
}
|
||||
|
||||
return Mono.empty();
|
||||
|
|
@ -492,7 +492,7 @@ public class McpStatelessAsyncServer {
|
|||
logger.debug("Removed resource handler: {}", resourceUri);
|
||||
}
|
||||
else {
|
||||
logger.warn("Resource with URI '{}' not found", resourceUri);
|
||||
logger.warn("Failed to remove a resource with URI '{}' (not found)", resourceUri);
|
||||
}
|
||||
return Mono.empty();
|
||||
});
|
||||
|
|
@ -554,7 +554,7 @@ public class McpStatelessAsyncServer {
|
|||
logger.debug("Removed resource template: {}", uriTemplate);
|
||||
}
|
||||
else {
|
||||
logger.warn("Ignore as a Resource Template with URI '{}' not found", uriTemplate);
|
||||
logger.warn("Failed to remove a resource template with URI '{}' (not found)", uriTemplate);
|
||||
}
|
||||
return Mono.empty();
|
||||
});
|
||||
|
|
@ -677,7 +677,7 @@ public class McpStatelessAsyncServer {
|
|||
return Mono.empty();
|
||||
}
|
||||
else {
|
||||
logger.warn("Ignore as a Prompt with name '{}' not found", promptName);
|
||||
logger.warn("Failed to remove a prompt with name '{}' (not found)", promptName);
|
||||
}
|
||||
|
||||
return Mono.empty();
|
||||
|
|
|
|||
|
|
@ -200,7 +200,7 @@ public class HttpServletStreamableServerTransportProvider extends HttpServlet
|
|||
session.sendNotification(method, params).block();
|
||||
}
|
||||
catch (Exception e) {
|
||||
logger.error("Failed to send message to session {}: {}", session.getId(), e.getMessage());
|
||||
logger.info("Failed to send message to session {}: {}", session.getId(), e.getMessage());
|
||||
}
|
||||
});
|
||||
});
|
||||
|
|
@ -233,12 +233,11 @@ public class HttpServletStreamableServerTransportProvider extends HttpServlet
|
|||
session.closeGracefully().block();
|
||||
}
|
||||
catch (Exception e) {
|
||||
logger.error("Failed to close session {}: {}", session.getId(), e.getMessage());
|
||||
logger.warn("Failed to close session {}: {}", session.getId(), e.getMessage());
|
||||
}
|
||||
});
|
||||
|
||||
this.sessions.clear();
|
||||
logger.debug("Graceful shutdown completed");
|
||||
}).then().doOnSuccess(v -> {
|
||||
sessions.clear();
|
||||
logger.debug("Graceful shutdown completed");
|
||||
|
|
|
|||
|
|
@ -124,7 +124,7 @@ public class McpClientSession implements McpSession {
|
|||
|
||||
private void dismissPendingResponses() {
|
||||
this.pendingResponses.forEach((id, sink) -> {
|
||||
logger.warn("Abruptly terminating exchange for request {}", id);
|
||||
logger.info("Abruptly terminating exchange for request {}", id);
|
||||
sink.error(new RuntimeException("MCP session with server terminated"));
|
||||
});
|
||||
this.pendingResponses.clear();
|
||||
|
|
@ -257,7 +257,8 @@ public class McpClientSession implements McpSession {
|
|||
});
|
||||
})).timeout(this.requestTimeout).handle((jsonRpcResponse, deliveredResponseSink) -> {
|
||||
if (jsonRpcResponse.error() != null) {
|
||||
logger.error("Error handling request: {}", jsonRpcResponse.error());
|
||||
logger.info("Server returned a JSON-RPC error when calling method {}: {}", method,
|
||||
jsonRpcResponse.error());
|
||||
deliveredResponseSink.error(new McpError(jsonRpcResponse.error()));
|
||||
}
|
||||
else {
|
||||
|
|
|
|||
|
|
@ -256,8 +256,8 @@ public class McpServerSession implements McpLoggableSession {
|
|||
// happening first
|
||||
logger.debug("Received notification: {}", notification);
|
||||
// TODO: in case of error, should the POST request be signalled?
|
||||
return handleIncomingNotification(notification, transportContext)
|
||||
.doOnError(error -> logger.error("Error handling notification: {}", error.getMessage()));
|
||||
return handleIncomingNotification(notification, transportContext).doOnError(
|
||||
error -> logger.warn("Error handling notification {}: {}", notification, error.getMessage()));
|
||||
}
|
||||
else {
|
||||
logger.warn("Received unknown message type: {}", message);
|
||||
|
|
|
|||
|
|
@ -84,11 +84,9 @@ public class DefaultJsonSchemaValidator implements JsonSchemaValidator {
|
|||
|
||||
}
|
||||
catch (JsonProcessingException e) {
|
||||
logger.error("Failed to validate CallToolResult: Error parsing schema: {}", e);
|
||||
return ValidationResponse.asInvalid("Error parsing tool JSON Schema: " + e.getMessage());
|
||||
}
|
||||
catch (Exception e) {
|
||||
logger.error("Failed to validate CallToolResult: Unexpected error: {}", e);
|
||||
return ValidationResponse.asInvalid("Unexpected validation error: " + e.getMessage());
|
||||
}
|
||||
}
|
||||
|
|
@ -113,7 +111,6 @@ public class DefaultJsonSchemaValidator implements JsonSchemaValidator {
|
|||
return ValidationResponse.asValid(null);
|
||||
}
|
||||
catch (Exception e) {
|
||||
logger.error("Failed to validate schema definition: {}", e.getMessage());
|
||||
return ValidationResponse.asInvalid("Failed to validate schema definition: " + e.getMessage());
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -83,11 +83,9 @@ public class DefaultJsonSchemaValidator implements JsonSchemaValidator {
|
|||
|
||||
}
|
||||
catch (JacksonException e) {
|
||||
logger.error("Failed to validate CallToolResult: Error parsing schema: {}", e);
|
||||
return ValidationResponse.asInvalid("Error parsing tool JSON Schema: " + e.getMessage());
|
||||
}
|
||||
catch (Exception e) {
|
||||
logger.error("Failed to validate CallToolResult: Unexpected error: {}", e);
|
||||
return ValidationResponse.asInvalid("Unexpected validation error: " + e.getMessage());
|
||||
}
|
||||
}
|
||||
|
|
@ -112,7 +110,6 @@ public class DefaultJsonSchemaValidator implements JsonSchemaValidator {
|
|||
return ValidationResponse.asValid(null);
|
||||
}
|
||||
catch (Exception e) {
|
||||
logger.error("Failed to validate schema definition: {}", e.getMessage());
|
||||
return ValidationResponse.asInvalid("Failed to validate schema definition: " + e.getMessage());
|
||||
}
|
||||
}
|
||||
|
|
|
|||
37
mcp-test/src/test/resources/logback-test.xml
Normal file
37
mcp-test/src/test/resources/logback-test.xml
Normal file
|
|
@ -0,0 +1,37 @@
|
|||
<?xml version="1.0" encoding="UTF-8"?>
|
||||
<!DOCTYPE configuration>
|
||||
|
||||
<configuration>
|
||||
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
|
||||
<encoder>
|
||||
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
|
||||
</encoder>
|
||||
</appender>
|
||||
|
||||
<appender name="DOCKER" class="ch.qos.logback.core.ConsoleAppender">
|
||||
<encoder>
|
||||
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level [DOCKER] %logger{36} - %msg%n</pattern>
|
||||
</encoder>
|
||||
</appender>
|
||||
|
||||
<!-- Testcontainers framework -->
|
||||
<logger name="org.testcontainers" level="INFO" additivity="false">
|
||||
<appender-ref ref="DOCKER"/>
|
||||
</logger>
|
||||
|
||||
<!-- Docker Java client -->
|
||||
<logger name="com.github.dockerjava" level="INFO" additivity="false">
|
||||
<appender-ref ref="DOCKER"/>
|
||||
</logger>
|
||||
|
||||
<!-- Container output (tc.<image-name> format used by Testcontainers) -->
|
||||
<logger name="tc" level="INFO" additivity="false">
|
||||
<appender-ref ref="DOCKER"/>
|
||||
</logger>
|
||||
|
||||
<logger name="io.modelcontextprotocol" level="INFO"/>
|
||||
|
||||
<root level="INFO">
|
||||
<appender-ref ref="STDOUT"/>
|
||||
</root>
|
||||
</configuration>
|
||||
Loading…
Reference in a new issue