feat: add safe HTTP trace logging

loong10k · loong10k · commit c19ac138981b · 2026-08-10T14:56:08.000+08:00
diff --git a/src/main/java/io/github/easy4j/hermes/HermesClient.java b/src/main/java/io/github/easy4j/hermes/HermesClient.java
@@ -264,6 +264,8 @@ private static void copyHttpConfig(HermesHttpClientConfig src, HermesHttpClientC
         target.setStreamKeepAliveMillis(src.getStreamKeepAliveMillis());
         target.setStreamEventQueueCapacity(src.getStreamEventQueueCapacity());
         target.setRetryOnConnectionFailure(src.isRetryOnConnectionFailure());
+        target.setDetailedLoggingEnabled(src.isDetailedLoggingEnabled());
+        target.setMaxLoggedBodyLength(src.getMaxLoggedBodyLength());
         target.setVerifySsl(src.isVerifySsl());
         target.setDefaultModel(src.getDefaultModel());
         target.setDefaultInstructions(src.getDefaultInstructions());
diff --git a/src/main/java/io/github/easy4j/hermes/HermesHttpClientConfig.java b/src/main/java/io/github/easy4j/hermes/HermesHttpClientConfig.java
@@ -94,6 +94,15 @@ public class HermesHttpClientConfig {
     /** 遇到失效连接等传输故障时是否允许 OkHttp 自动恢复。 */
     private boolean retryOnConnectionFailure = true;
 
+    /**
+     * 是否输出请求头、请求体及响应体等详细诊断信息。
+     * <p>默认关闭；基础请求生命周期仍使用 DEBUG 日志。</p>
+     */
+    private boolean detailedLoggingEnabled = false;
+
+    /** 详细日志中请求体、响应体的最大字符数。 */
+    private int maxLoggedBodyLength = 2_000;
+
     /**
      * 是否校验 HTTPS 证书；为 false 时关闭校验（仅建议开发环境）。
      */
diff --git a/src/main/java/io/github/easy4j/hermes/api/HermesHttpClient.java b/src/main/java/io/github/easy4j/hermes/api/HermesHttpClient.java
@@ -17,6 +17,8 @@
 
 import java.io.IOException;
 import java.util.*;
+import java.util.concurrent.atomic.AtomicLong;
+import okio.Buffer;
 
 /**
  * Hermes Server HTTP 客户端，封装 REST API。
@@ -26,6 +28,7 @@
 public class HermesHttpClient implements AutoCloseable {
 
     private static final MediaType JSON = MediaType.get("application/json; charset=utf-8");
+    private static final AtomicLong REQUEST_SEQUENCE = new AtomicLong();
 
     private final HermesHttpClientConfig config;
     private final ObjectMapper objectMapper;
@@ -49,6 +52,11 @@ private HermesHttpClient(HermesHttpClientConfig config, ObjectMapper objectMappe
                 .configure(DeserializationFeature.FAIL_ON_UNKNOWN_PROPERTIES, false) : objectMapper;
         this.httpClient = Objects.requireNonNull(httpClient, "httpClient");
         this.ownsHttpClient = ownsHttpClient;
+        log.debug("Hermes HTTP client initialized: baseUrl={}, connectTimeoutMs={}, readTimeoutMs={}, "
+                        + "callTimeoutMs={}, retryOnConnectionFailure={}, detailedLoggingEnabled={}",
+                config.getBaseUrl(), config.getConnectTimeoutMillis(), config.getReadTimeoutMillis(),
+                config.getCallTimeoutMillis(), config.isRetryOnConnectionFailure(),
+                config.isDetailedLoggingEnabled());
     }
 
     // ============================================================
@@ -377,16 +385,23 @@ private <T> T execute(Request request, Class<T> type) {
     }
 
     private <T> T execute(Request request, Class<T> type, HttpCallCancellation cancellation) {
+        long requestId = beginTrace(request);
+        long startedAt = System.nanoTime();
         Call call = httpClient.newCall(request);
         AutoCloseable registration = cancellation != null ? cancellation.onCancel(call::cancel) : null;
         try (Response response = call.execute()) {
             String respBody = response.body() != null ? response.body().string() : "";
+            logResponse(requestId, request, response.code(), respBody, startedAt);
             if (!response.isSuccessful()) {
                 throw new HermesHttpException(response.code(), respBody);
             }
             return objectMapper.readValue(respBody, type);
         } catch (IOException e) {
+            logFailure(requestId, request, startedAt, e);
             throw new HermesHttpException("HTTP request failed: " + e.getMessage(), e);
+        } catch (RuntimeException e) {
+            logFailure(requestId, request, startedAt, e);
+            throw e;
         } finally {
             closeRegistration(registration);
         }
@@ -404,17 +419,81 @@ private void closeRegistration(AutoCloseable registration) {
     }
 
     private <T> T executeList(Request request, TypeReference<T> typeRef) {
+        long requestId = beginTrace(request);
+        long startedAt = System.nanoTime();
         try (Response response = httpClient.newCall(request).execute()) {
             String respBody = response.body() != null ? response.body().string() : "";
+            logResponse(requestId, request, response.code(), respBody, startedAt);
             if (!response.isSuccessful()) {
                 throw new HermesHttpException(response.code(), respBody);
             }
             return objectMapper.readValue(respBody, typeRef);
         } catch (IOException e) {
+            logFailure(requestId, request, startedAt, e);
             throw new HermesHttpException("HTTP request failed: " + e.getMessage(), e);
+        } catch (RuntimeException e) {
+            logFailure(requestId, request, startedAt, e);
+            throw e;
         }
     }
 
+    private long beginTrace(Request request) {
+        long requestId = REQUEST_SEQUENCE.incrementAndGet();
+        log.debug("HTTP request started: requestId={}, method={}, url={}",
+                requestId, request.method(), request.url());
+        if (config.isDetailedLoggingEnabled()) {
+            log.debug("HTTP request details: requestId={}, headers={}, body={}", requestId,
+                    redactHeaders(request.headers()), requestBody(request));
+        }
+        return requestId;
+    }
+
+    private void logResponse(long requestId, Request request, int status, String body, long startedAt) {
+        log.debug("HTTP request completed: requestId={}, method={}, url={}, status={}, bodyLength={}, elapsedMs={}",
+                requestId, request.method(), request.url(), status, body.length(), elapsedMillis(startedAt));
+        if (config.isDetailedLoggingEnabled()) {
+            log.debug("HTTP response body: requestId={}, body={}", requestId, truncate(body));
+        }
+    }
+
+    private void logFailure(long requestId, Request request, long startedAt, Exception error) {
+        log.warn("HTTP request failed: requestId={}, method={}, url={}, elapsedMs={}, error={}",
+                requestId, request.method(), request.url(), elapsedMillis(startedAt), error.getMessage());
+    }
+
+    private long elapsedMillis(long startedAt) {
+        return (System.nanoTime() - startedAt) / 1_000_000L;
+    }
+
+    private String requestBody(Request request) {
+        if (Objects.isNull(request.body())) {
+            return "";
+        }
+        try {
+            Buffer buffer = new Buffer();
+            request.body().writeTo(buffer);
+            return truncate(buffer.readUtf8());
+        } catch (IOException error) {
+            return "<unavailable:" + error.getMessage() + ">";
+        }
+    }
+
+    private String truncate(String value) {
+        int limit = Math.max(0, config.getMaxLoggedBodyLength());
+        return value.length() <= limit ? value : value.substring(0, limit) + "...<truncated>";
+    }
+
+    private Headers redactHeaders(Headers headers) {
+        Headers.Builder safe = headers.newBuilder();
+        for (String name : headers.names()) {
+            String lowerName = name.toLowerCase();
+            if ("authorization".equals(lowerName) || lowerName.contains("token") || lowerName.contains("key")) {
+                safe.set(name, "██");
+            }
+        }
+        return safe.build();
+    }
+
     private String toJson(Object body) {
         try {
             return objectMapper.writeValueAsString(body);
diff --git a/src/main/java/io/github/easy4j/hermes/api/HermesSseClient.java b/src/main/java/io/github/easy4j/hermes/api/HermesSseClient.java
@@ -57,6 +57,10 @@ public HermesSseClient(HermesHttpClientConfig config, ObjectMapper objectMapper,
         this.ownsHttpClient = Objects.isNull(httpClient);
         this.httpClient = this.ownsHttpClient ? HermesOkHttpClientFactory.create(config) : httpClient;
         this.streamExecutor = createStreamExecutor(config);
+        log.debug("Hermes SSE client initialized: baseUrl={}, corePoolSize={}, maxPoolSize={}, queueCapacity={}, "
+                        + "eventQueueCapacity={}, detailedLoggingEnabled={}", config.getBaseUrl(),
+                config.getStreamCorePoolSize(), config.getStreamMaxPoolSize(), config.getStreamQueueCapacity(),
+                config.getStreamEventQueueCapacity(), config.isDetailedLoggingEnabled());
     }
 
     private static ExecutorService createStreamExecutor(HermesHttpClientConfig config) {
@@ -163,6 +167,8 @@ private void doSubscribePost(String url,
         };
         try {
             Request request = buildPostSseRequest(url, requestBody, headers);
+            long startedAt = System.nanoTime();
+            log.debug("SSE chat subscription started: url={}", url);
             Call call = httpClient.newCall(request);
             sub.callRef.set(call);
             try (Response response = call.execute()) {
@@ -171,6 +177,8 @@ private void doSubscribePost(String url,
                     onError.accept(new HermesHttpException(response.code(), body));
                     return;
                 }
+                log.info("SSE chat connected: url={}, status={}, elapsedMs={}", url, response.code(),
+                        (System.nanoTime() - startedAt) / 1_000_000L);
                 if (response.body() != null) {
                     parseSseSource(response.body().source(), consumer, completeOnce, sub);
                 }
diff --git a/src/test/java/io/github/easy4j/hermes/HermesHttpClientConfigTest.java b/src/test/java/io/github/easy4j/hermes/HermesHttpClientConfigTest.java
@@ -7,13 +7,16 @@
 import io.github.easy4j.hermes.api.sse.StreamingChatResponse;
 
 import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.junit.jupiter.api.Assertions.assertFalse;
 
 class HermesHttpClientConfigTest {
 
     @Test
     void shouldExposeUnifiedHttpProperties() {
         HermesHttpClientConfig config = new HermesHttpClientConfig();
         assertEquals(HttpResponseMode.BLOCKING, config.getMode());
+        assertFalse(config.isDetailedLoggingEnabled());
+        assertEquals(2_000, config.getMaxLoggedBodyLength());
         config.setBaseUrl("http://hermes");
         assertEquals("http://hermes", config.getBaseUrl());
 
