logging: render formattedMessage on stdout; tool calls log key-value pairs

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

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.
  *
  * <p>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<CallToolResult> 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;
   }

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;

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);
   }
 }

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.

domains/platform/resources/logback.xml

@@ -3,8 +3,13 @@
     <!-- One JSON object per line, logback's own encoder — no new
          dependency. The stats pipeline parses these offline (#1459), and
          the epoch-millis timestamp is absolute, which the old date-less
-         pattern was not (#1456). LogbackConfigTest pins the shape. -->
-    <encoder class="ch.qos.logback.classic.encoder.JsonEncoder"/>
+         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. -->
+    <encoder class="ch.qos.logback.classic.encoder.JsonEncoder">
+      <withFormattedMessage>true</withFormattedMessage>
+    </encoder>
     <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
       <level>INFO</level>
     </filter>