diff --git a/domains/games/apis/mcpserver/README.md b/domains/games/apis/mcpserver/README.md index c7689ac1..1e706f75 100644 --- a/domains/games/apis/mcpserver/README.md +++ b/domains/games/apis/mcpserver/README.md @@ -247,8 +247,9 @@ Environment variables: ## Logging -Every tool call logs one line — name, duration, outcome — on the -`com.muchq.games.mcpserver.tools.ToolCallLog` logger: INFO for a success, WARN +Every tool call logs one line on the `com.muchq.games.mcpserver.tools.ToolCallLog` +logger: message `tool_call`, with `tool`, `ms`, and `outcome` as key-value pairs +(the `kvpList` of the JSON line, the shape the stats pipeline reads): INFO for a success, WARN when the tool answered `isError: true`, ERROR with the stack when an exception escaped the tool (the framework's JSON-RPC error mapping still applies). Arguments are not logged. A call the framework rejects before the tool method diff --git a/domains/games/apis/mcpserver/src/main/java/com/muchq/games/mcpserver/tools/ToolCallLog.java b/domains/games/apis/mcpserver/src/main/java/com/muchq/games/mcpserver/tools/ToolCallLog.java index 3b584a86..781a2b04 100644 --- a/domains/games/apis/mcpserver/src/main/java/com/muchq/games/mcpserver/tools/ToolCallLog.java +++ b/domains/games/apis/mcpserver/src/main/java/com/muchq/games/mcpserver/tools/ToolCallLog.java @@ -4,11 +4,14 @@ import java.util.function.Supplier; import org.slf4j.Logger; import org.slf4j.LoggerFactory; +import org.slf4j.spi.LoggingEventBuilder; /** - * One log line per tool call: name, duration, outcome. Every {@code @Tool} method wraps its body in - * {@link #logged}, which is the only server-side trace a call leaves — micronaut-mcp's dispatch - * (ToolRegistry) is final with private handlers, so there is no framework seam to hang this on. + * One log line per tool call, message {@code tool_call} with key-value pairs {@code tool}, {@code + * ms}, and {@code outcome}, so the line aggregates without parsing its text. Every {@code @Tool} + * method wraps its body in {@link #logged}, which is the only server-side trace a call leaves — + * micronaut-mcp's dispatch (ToolRegistry) is final with private handlers, so there is no framework + * seam to hang this on. * *

Outcomes map to levels: a successful result is INFO, a result the tool flagged {@code isError} * is WARN, and an exception that escapes the tool is ERROR with the stack — then rethrown, so the @@ -27,23 +30,33 @@ final class ToolCallLog { private ToolCallLog() {} + static final String MESSAGE = "tool_call"; + static CallToolResult logged(String tool, Supplier call) { long start = System.nanoTime(); CallToolResult result; try { result = call.get(); } catch (RuntimeException | Error e) { - LOG.error("tool={} ms={} outcome=threw", tool, elapsedMs(start), e); + line(LOG.atError().setCause(e), tool, elapsedMs(start), "threw"); throw e; } if (Boolean.TRUE.equals(result.isError())) { - LOG.warn("tool={} ms={} outcome=error", tool, elapsedMs(start)); + line(LOG.atWarn(), tool, elapsedMs(start), "error"); } else { - LOG.info("tool={} ms={} outcome=ok", tool, elapsedMs(start)); + line(LOG.atInfo(), tool, elapsedMs(start), "ok"); } return result; } + private static void line(LoggingEventBuilder builder, String tool, long ms, String outcome) { + builder + .addKeyValue("tool", tool) + .addKeyValue("ms", ms) + .addKeyValue("outcome", outcome) + .log(MESSAGE); + } + private static long elapsedMs(long startNanos) { return (System.nanoTime() - startNanos) / 1_000_000; } diff --git a/domains/games/apis/mcpserver/src/test/java/com/muchq/games/mcpserver/McpToolCallLoggingTest.java b/domains/games/apis/mcpserver/src/test/java/com/muchq/games/mcpserver/McpToolCallLoggingTest.java index 501ec26e..accb8beb 100644 --- a/domains/games/apis/mcpserver/src/test/java/com/muchq/games/mcpserver/McpToolCallLoggingTest.java +++ b/domains/games/apis/mcpserver/src/test/java/com/muchq/games/mcpserver/McpToolCallLoggingTest.java @@ -22,6 +22,7 @@ import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; import org.slf4j.LoggerFactory; +import org.slf4j.event.KeyValuePair; /** * A tool call leaves a server-side line: name, duration, outcome. Asserted through the real server @@ -119,10 +120,19 @@ public void aSuccessfulToolCallLogsOneInfoLineNamingTheTool() throws Exception { assertThat(appender.list).hasSize(1); ILoggingEvent event = appender.list.get(0); assertThat(event.getLevel()).isEqualTo(Level.INFO); - assertThat(event.getFormattedMessage()) - .contains("tool=server_time") - .contains("ms=") - .contains("outcome=ok"); + assertThat(event.getMessage()).isEqualTo("tool_call"); + assertThat(kv(event, "tool")).isEqualTo("server_time"); + assertThat(kv(event, "outcome")).isEqualTo("ok"); + assertThat(kv(event, "ms")).isInstanceOf(Long.class); + } + + private static Object kv(ILoggingEvent event, String key) { + for (KeyValuePair pair : java.util.Objects.requireNonNull(event.getKeyValuePairs())) { + if (pair.key.equals(key)) { + return pair.value; + } + } + throw new AssertionError("no key-value pair " + key + " on " + event); } @Test @@ -137,10 +147,9 @@ public void aToolsOwnRejectionLogsAWarnLineNamingTheToolButNotItsArguments() thr assertThat(appender.list).hasSize(1); ILoggingEvent event = appender.list.get(0); assertThat(event.getLevel()).isEqualTo(Level.WARN); - assertThat(event.getFormattedMessage()) - .contains("tool=chess_com_games") - .contains("outcome=error"); - assertThat(event.getFormattedMessage()) + assertThat(kv(event, "tool")).isEqualTo("chess_com_games"); + assertThat(kv(event, "outcome")).isEqualTo("error"); + assertThat(event.getFormattedMessage() + event.getKeyValuePairs()) .as("arguments are caller data and stay out of the log — README's stated contract") .doesNotContain("sentinel-username-x9"); } @@ -175,7 +184,8 @@ public void everyAdvertisedToolLogsExactlyOneLineNamingItself() throws Exception assertThat(appender.list).as("%s must log exactly one line per call", name).hasSize(1); ILoggingEvent event = appender.list.get(0); - assertThat(event.getFormattedMessage()).contains("tool=" + name).contains("ms="); + assertThat(kv(event, "tool")).isEqualTo(name); + assertThat(kv(event, "ms")).isInstanceOf(Long.class); // server_time is the one tool that succeeds without the network; everything else is a // rejection or an unreachable-one_d4 report, both on the isError channel. Level expected = "server_time".equals(name) ? Level.INFO : Level.WARN; diff --git a/domains/games/apis/mcpserver/src/test/java/com/muchq/games/mcpserver/tools/ToolCallLogTest.java b/domains/games/apis/mcpserver/src/test/java/com/muchq/games/mcpserver/tools/ToolCallLogTest.java index 24fc9e07..4efb4820 100644 --- a/domains/games/apis/mcpserver/src/test/java/com/muchq/games/mcpserver/tools/ToolCallLogTest.java +++ b/domains/games/apis/mcpserver/src/test/java/com/muchq/games/mcpserver/tools/ToolCallLogTest.java @@ -8,10 +8,12 @@ import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.core.read.ListAppender; import io.modelcontextprotocol.spec.McpSchema.CallToolResult; +import java.util.Objects; import org.junit.jupiter.api.AfterEach; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; import org.slf4j.LoggerFactory; +import org.slf4j.event.KeyValuePair; public class ToolCallLogTest { @@ -31,6 +33,15 @@ public void detachAppender() { logger.detachAppender(appender); } + static Object kv(ILoggingEvent event, String key) { + for (KeyValuePair pair : Objects.requireNonNull(event.getKeyValuePairs())) { + if (pair.key.equals(key)) { + return pair.value; + } + } + throw new AssertionError("no key-value pair " + key + " on " + event); + } + @Test public void aSuccessfulCallIsLoggedAtInfoAndItsResultReturnedUntouched() { CallToolResult result = ToolResults.text("payload"); @@ -41,7 +52,10 @@ public void aSuccessfulCallIsLoggedAtInfoAndItsResultReturnedUntouched() { assertThat(appender.list).hasSize(1); ILoggingEvent event = appender.list.get(0); assertThat(event.getLevel()).isEqualTo(Level.INFO); - assertThat(event.getFormattedMessage()).contains("tool=server_time").contains("ms="); + assertThat(event.getMessage()).isEqualTo("tool_call"); + assertThat(kv(event, "tool")).isEqualTo("server_time"); + assertThat(kv(event, "outcome")).isEqualTo("ok"); + assertThat(kv(event, "ms")).isInstanceOf(Long.class); } @Test @@ -51,7 +65,8 @@ public void aResultTheToolFlaggedAsAnErrorIsLoggedAtWarn() { assertThat(appender.list).hasSize(1); ILoggingEvent event = appender.list.get(0); assertThat(event.getLevel()).isEqualTo(Level.WARN); - assertThat(event.getFormattedMessage()).contains("tool=chess_com_games"); + assertThat(kv(event, "tool")).isEqualTo("chess_com_games"); + assertThat(kv(event, "outcome")).isEqualTo("error"); } @Test @@ -70,7 +85,8 @@ public void anUncaughtExceptionIsLoggedAtErrorWithTheStackAndRethrown() { assertThat(appender.list).hasSize(1); ILoggingEvent event = appender.list.get(0); assertThat(event.getLevel()).isEqualTo(Level.ERROR); - assertThat(event.getFormattedMessage()).contains("tool=index_chess_games"); + assertThat(kv(event, "tool")).isEqualTo("index_chess_games"); + assertThat(kv(event, "outcome")).isEqualTo("threw"); assertThat(event.getThrowableProxy().getMessage()).isEqualTo("connection refused"); } @@ -91,8 +107,6 @@ public void theLoggedDurationCoversTheCall() { return ToolResults.text("x"); }); - String message = appender.list.get(0).getFormattedMessage(); - long ms = Long.parseLong(message.replaceAll(".*ms=(\\d+).*", "$1")); - assertThat(ms).isGreaterThanOrEqualTo(30); + assertThat((Long) kv(appender.list.get(0), "ms")).isGreaterThanOrEqualTo(30); } } diff --git a/domains/platform/libs/logging/src/test/java/com/muchq/platform/logging/LogbackConfigTest.java b/domains/platform/libs/logging/src/test/java/com/muchq/platform/logging/LogbackConfigTest.java index d0fb267e..87406de4 100644 --- a/domains/platform/libs/logging/src/test/java/com/muchq/platform/logging/LogbackConfigTest.java +++ b/domains/platform/libs/logging/src/test/java/com/muchq/platform/logging/LogbackConfigTest.java @@ -75,15 +75,16 @@ public void theSharedConfigEmitsOneParseableJsonObjectPerLineWithAnAbsoluteTimes Instant.parse("2026-01-01T00:00:00Z").toEpochMilli(), Instant.parse("2100-01-01T00:00:00Z").toEpochMilli()); - // The parameterized case is what services actually write, and - // JsonEncoder's contract there is NOT "message is the rendered text": - // the raw template rides in "message" and the values in "arguments". - // Anything reading these lines offline has to know that, so the - // semantic is pinned, not discovered. + // The parameterized case is what services actually write. "message" + // is the raw template and "arguments" the values — what machine + // readers key on — and "formattedMessage" is the rendered line, for + // anyone reading the stream by eye. JsonNode parameterized = lineContaining(captured.toString(UTF_8), "widget {} failed"); assertThat(parameterized.get("message").asText()).isEqualTo("widget {} failed after {} tries"); assertThat(parameterized.get("arguments").get(0).asText()).isEqualTo("w-7"); assertThat(parameterized.get("arguments").get(1).asText()).isEqualTo("3"); + assertThat(parameterized.get("formattedMessage").asText()) + .isEqualTo("widget w-7 failed after 3 tries"); // An ERROR with a throwable — the line Sentry and any alerting reads — // stays one parseable object with the exception structured inside it. diff --git a/domains/platform/resources/logback.xml b/domains/platform/resources/logback.xml index 962c9697..8a9a0722 100644 --- a/domains/platform/resources/logback.xml +++ b/domains/platform/resources/logback.xml @@ -3,8 +3,13 @@ - + pattern was not (#1456). "message" is the raw template and + "arguments" the values, for machine readers; "formattedMessage" + is the rendered line, for eyes on docker logs. LogbackConfigTest + pins the shape. --> + + true + INFO