Add logging through slf4j (#6)

CHANGELOG.md

@@ -2,6 +2,7 @@
 
 ## Unreleased
 
+- Logging through slf4j on the `io.github.premocloud.typesafe` logger: `DEBUG` for one line per request with status and elapsed, plus retries and connection failures; `TRACE` for the wire in both directions. Nothing at `INFO` or above. Credential headers are masked. Adds `org.slf4j:slf4j-api` (#6).
 - `TypeSafePaymentRequiredException` (402) and `TypeSafePayloadTooLargeException` (413) join the other status-specific exceptions; both statuses previously fell through to the generic `TypeSafeApiException` (#8).
 
 ## 0.3.0 - 2026-09-19

README.md

@@ -8,7 +8,7 @@ TypeSafe AI. It follows the conventions of the official [Python](https://github.
 [JavaScript](https://github.com/typesafe-ai/typesafe-sdk-js) SDKs so the three read alike. TypeSafe is a trademark of
 its owner; the name is used here only to describe what the library connects to.
 
-Requires Java 17 or newer. Depends only on Jackson.
+Requires Java 17 or newer.
 
 ## Install
 
@@ -173,6 +173,35 @@ TypeSafeClient client = TypeSafeClient.builder()
         .build();
 ```
 
+## Logging
+
+The client logs through slf4j on the `io.github.premocloud.typesafe` logger. Set its level the way you set any
+library's; there is no environment variable, because slf4j has no library-side level setting and configuring the
+logging environment is the application's job.
+
+| Level | What you get |
+| --- | --- |
+| `DEBUG` | one line per request with its status and how long it took, plus a line per retry and per connection failure |
+| `TRACE` | the above, plus the wire in both directions: method, url, headers, body |
+| `INFO` and above | nothing, so a stock application sees none of this; failures are thrown, not logged |
+
+```xml
+<logger name="io.github.premocloud.typesafe" level="DEBUG"/>
+```
+
+```properties
+logging.level.io.github.premocloud.typesafe=DEBUG
+```
+
+```
+TRACE io.github.premocloud.typesafe - req-3f9a1c -> POST https://api.typesafe.ai/v1/systemone headers={Authorization=***, ...} body={"state":...}
+DEBUG io.github.premocloud.typesafe - req-3f9a1c <- 200 in 214ms (request req_01a0...)
+TRACE io.github.premocloud.typesafe - req-3f9a1c <- 200 headers={x-typesafe-request-id=req_01a0..., ...} body={"model":"jev-1.13.0",...}
+```
+
+Credential headers are masked, including any of your own containing `token` or `secret`. **Bodies are not masked**, so
+`TRACE` puts the state you are classifying into the log.
+
 ## Spring Boot
 
 Add `io.github.premo-cloud:typesafe-sdk-spring-boot-starter` and set one property:

typesafe-sdk/build.gradle.kts

@@ -3,9 +3,12 @@ description = "Community Java client for the TypeSafe System One API"
 dependencies {
     api("com.fasterxml.jackson.core:jackson-databind:2.15.4")
     api("org.jspecify:jspecify:1.0.1")
+    api("org.slf4j:slf4j-api:2.0.16")
 
     testImplementation(platform("org.junit:junit-bom:5.14.4"))
     testImplementation("org.junit.jupiter:junit-jupiter")
+    // A binding with a programmable appender, so the tests can assert on what was logged.
+    testImplementation("ch.qos.logback:logback-classic:1.5.18")
     testRuntimeOnly("org.junit.platform:junit-platform-launcher")
 }
 

typesafe-sdk/src/main/java/io/github/premocloud/typesafe/Logging.java

@@ -0,0 +1,84 @@
+package io.github.premocloud.typesafe;
+
+import org.jspecify.annotations.Nullable;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+import java.net.http.HttpHeaders;
+import java.util.List;
+import java.util.Locale;
+import java.util.Set;
+import java.util.concurrent.ThreadLocalRandom;
+import java.util.stream.Collectors;
+
+/**
+ * What the client logs, tiered as the official SDKs log it.
+ *
+ * <p>{@code DEBUG} is one line per request with its status, elapsed time and request id, plus a line
+ * for each retry and each connection failure. {@code TRACE} adds the wire in both directions: method,
+ * url, headers and body. Nothing is logged at {@code INFO} or above, because a failure is already
+ * thrown and the exception carries more than a log line would.
+ *
+ * <p>Set the level on the {@code io.github.premocloud.typesafe} logger, as for any library. There is
+ * no environment variable: slf4j has no library-side level setting, and a library should let the
+ * application configure its own logging.
+ *
+ * <p>Credential headers are masked. Bodies are not, so {@code TRACE} puts the state being classified
+ * into the log; both official SDKs document the same.
+ */
+final class Logging {
+
+    static final Logger LOG = LoggerFactory.getLogger("io.github.premocloud.typesafe");
+
+    /** Masked in full. The union of what the official Python and JavaScript SDKs cover. */
+    private static final Set<String> SECRET_HEADERS = Set.of(
+            "authorization", "proxy-authorization", "api-key", "x-api-key", "cookie", "set-cookie");
+
+    private Logging() {
+    }
+
+    /**
+     * A short opaque tag for one logical call, shared by every attempt it makes, so the lines of
+     * interleaved async calls can be told apart. Random rather than counted: no shared state, and no
+     * collisions across restarts or replicas in an aggregated log.
+     */
+    static String tag() {
+        return String.format("req-%06x", ThreadLocalRandom.current().nextInt(1 << 24));
+    }
+
+    /** Guards the wire calls, so a redacted header string is never built when TRACE is off. */
+    static boolean wireEnabled() {
+        return LOG.isTraceEnabled();
+    }
+
+    /**
+     * One direction of the exchange.
+     *
+     * @param arrow {@code ->} for what was sent, {@code <-} for what came back
+     */
+    static void wire(String tag, String arrow, String summary, HttpHeaders headers, @Nullable String body) {
+        LOG.trace("{} {} {} headers={} body={}", tag, arrow, summary, redact(headers), body == null ? "" : body);
+    }
+
+    /**
+     * Header names and values with credentials masked. The only place redaction happens, so no call
+     * site can leak one.
+     */
+    private static String redact(HttpHeaders headers) {
+        return headers.map().entrySet().stream()
+                .map(header -> header.getKey() + "=" + value(header.getKey(), header.getValue()))
+                .collect(Collectors.joining(", ", "{", "}"));
+    }
+
+    private static String value(String name, List<String> values) {
+        String lower = name.toLowerCase(Locale.ROOT);
+
+        // The named set covers what is documented; the substring check catches a header this SDK
+        // never anticipated, which a caller can add through Builder.header.
+        if (SECRET_HEADERS.contains(lower) || lower.contains("token") || lower.contains("secret")) {
+            return "***";
+        }
+
+        return values.isEmpty() ? "" : values.get(0);
+    }
+}

typesafe-sdk/src/main/java/io/github/premocloud/typesafe/TypeSafeClient.java

@@ -5,6 +5,7 @@
 import com.fasterxml.jackson.databind.JsonMappingException;
 import com.fasterxml.jackson.databind.ObjectMapper;
 import org.jspecify.annotations.Nullable;
+import org.slf4j.Logger;
 
 import java.io.IOException;
 import java.net.URI;
@@ -56,6 +57,8 @@ public final class TypeSafeClient {
     private static final String SDK_NAME = "typesafe-sdk";
     private static final String VERSION = Objects.requireNonNullElse(TypeSafeClient.class.getPackage().getImplementationVersion(), "dev");
 
+    private static final Logger LOG = Logging.LOG;
+
     private final HttpClient httpClient;
     private final ObjectMapper objectMapper;
     private final String apiKey;
@@ -192,10 +195,18 @@ private <T> CompletableFuture<T> postAsync(String path, Object body, Class<T> ty
 
         return sendAsync(HttpRequest.newBuilder(URI.create(baseUrl + path))
                 .header("Content-Type", "application/json")
-                .POST(HttpRequest.BodyPublishers.ofString(json)), type, options);
+                .POST(HttpRequest.BodyPublishers.ofString(json)), type, options, json);
+    }
+
+    /** What logging needs about one request, the same for every attempt it makes. */
+    private record Call(String tag, @Nullable String requestBody) {
     }
 
     private <T> CompletableFuture<T> sendAsync(HttpRequest.Builder template, Class<T> type, RequestOptions options) {
+        return sendAsync(template, type, options, null);
+    }
+
+    private <T> CompletableFuture<T> sendAsync(HttpRequest.Builder template, Class<T> type, RequestOptions options, @Nullable String requestBody) {
         Duration timeout = Objects.requireNonNullElse(options.timeout(), this.timeout);
         RetryPolicy retryPolicy = options.resolveRetryPolicy(this.retryPolicy);
         Map<String, String> headers = new LinkedHashMap<>(defaultHeaders);
@@ -208,13 +219,21 @@ private <T> CompletableFuture<T> sendAsync(HttpRequest.Builder template, Class<T
                 .header("X-TypeSafe-Runtime", "java/" + System.getProperty("java.version"));
         headers.forEach(template::header);
 
-        return attemptAsync(template, type, timeout, retryPolicy, 0);
+        return attemptAsync(template, type, timeout, retryPolicy, 0,
+                new Call(Logging.tag(), requestBody));
     }
 
     /** One attempt, its retry decision, and its exception mapping: the path both blocking and async calls share. */
-    private <T> CompletableFuture<T> attemptAsync(HttpRequest.Builder template, Class<T> type, Duration timeout, RetryPolicy retryPolicy, int attempt) {
+    private <T> CompletableFuture<T> attemptAsync(HttpRequest.Builder template, Class<T> type, Duration timeout, RetryPolicy retryPolicy, int attempt, Call call) {
         // Setup throws here (a bad URI, a closed client) propagate synchronously, as HttpClient.sendAsync does.
         HttpRequest httpRequest = attempt == 0 ? template.build() : template.copy().header(RETRY_COUNT_HEADER, Integer.toString(attempt)).build();
+
+        if (Logging.wireEnabled()) {
+            Logging.wire(call.tag(), "->", httpRequest.method() + " " + httpRequest.uri(),
+                    httpRequest.headers(), call.requestBody());
+        }
+
+        long startedNanos = System.nanoTime();
         CompletableFuture<HttpResponse<String>> sent = httpClient.sendAsync(httpRequest, HttpResponse.BodyHandlers.ofString());
 
         return sent.<CompletableFuture<T>>handle((response, error) -> {
@@ -223,16 +242,20 @@ private <T> CompletableFuture<T> attemptAsync(HttpRequest.Builder template, Clas
                     Throwable cause = unwrap(error);
 
                     if (cause instanceof HttpTimeoutException httpTimeout) {
+                        LOG.debug("{} timed out after {}ms", call.tag(), elapsedMs(startedNanos));
+
                         if (retryPolicy.retryTimeouts() && attempt < retryPolicy.maxRetries()) {
-                            return retryAsync(backoff(retryPolicy, attempt, Optional.empty()), template, type, timeout, retryPolicy, attempt + 1);
+                            return retryAsync(backoff(retryPolicy, attempt, Optional.empty()), template, type, timeout, retryPolicy, attempt + 1, call);
                         }
 
                         return CompletableFuture.<T>failedFuture(new TypeSafeTimeoutException(timeout, httpTimeout));
                     }
 
                     if (cause instanceof IOException ioException) {
+                        LOG.debug("{} <- {} after {}ms", call.tag(), ioException.getClass().getSimpleName(), elapsedMs(startedNanos));
+
                         if (retryPolicy.retryConnectionErrors() && attempt < retryPolicy.maxRetries()) {
-                            return retryAsync(backoff(retryPolicy, attempt, Optional.empty()), template, type, timeout, retryPolicy, attempt + 1);
+                            return retryAsync(backoff(retryPolicy, attempt, Optional.empty()), template, type, timeout, retryPolicy, attempt + 1, call);
                         }
 
                         return CompletableFuture.<T>failedFuture(new TypeSafeConnectionException("Connection error: " + ioException.getMessage(), ioException));
@@ -242,14 +265,23 @@ private <T> CompletableFuture<T> attemptAsync(HttpRequest.Builder template, Clas
                 }
 
                 int status = response.statusCode();
+                LOG.debug("{} <- {} in {}ms (request {})", call.tag(), status, elapsedMs(startedNanos),
+                        response.headers().firstValue(TypeSafeApiException.REQUEST_ID_HEADER).orElse("-"));
+
+                if (Logging.wireEnabled()) {
+                    Logging.wire(call.tag(), "<-", String.valueOf(status), response.headers(), response.body());
+                }
 
                 if (status >= 200 && status < 300) {
                     return CompletableFuture.completedFuture(deserialize(response.body(), type));
                 }
 
                 if (retryPolicy.retriesStatus(status) && attempt < retryPolicy.maxRetries()) {
-                    return retryAsync(backoff(retryPolicy, attempt, retryPolicy.respectRetryAfter() ? RetryAfter.parse(response.headers()) : Optional.empty()),
-                            template, type, timeout, retryPolicy, attempt + 1);
+                    Duration delay = backoff(retryPolicy, attempt, retryPolicy.respectRetryAfter() ? RetryAfter.parse(response.headers()) : Optional.empty());
+                    LOG.debug("{} retrying in {}ms (retry {}/{}) after {}", call.tag(), delay.toMillis(),
+                            attempt + 1, retryPolicy.maxRetries(), status);
+
+                    return retryAsync(delay, template, type, timeout, retryPolicy, attempt + 1, call);
                 }
 
                 return CompletableFuture.<T>failedFuture(TypeSafeApiException.fromResponse(status, response.body(), response.headers()));
@@ -260,8 +292,8 @@ private <T> CompletableFuture<T> attemptAsync(HttpRequest.Builder template, Clas
     }
 
     /** Schedules the next attempt on the JDK's shared delayer, so backoff never parks a thread of ours. */
-    private <T> CompletableFuture<T> retryAsync(Duration delay, HttpRequest.Builder template, Class<T> type, Duration timeout, RetryPolicy retryPolicy, int attempt) {
-        return CompletableFuture.supplyAsync(() -> attemptAsync(template, type, timeout, retryPolicy, attempt),
+    private <T> CompletableFuture<T> retryAsync(Duration delay, HttpRequest.Builder template, Class<T> type, Duration timeout, RetryPolicy retryPolicy, int attempt, Call call) {
+        return CompletableFuture.supplyAsync(() -> attemptAsync(template, type, timeout, retryPolicy, attempt, call),
                         CompletableFuture.delayedExecutor(delay.toMillis(), TimeUnit.MILLISECONDS))
                 .thenCompose(next -> next);
     }
@@ -292,6 +324,10 @@ static <T> T blocking(CompletableFuture<T> future) {
         }
     }
 
+    private static long elapsedMs(long startedNanos) {
+        return (System.nanoTime() - startedNanos) / 1_000_000;
+    }
+
     /** Completion and execution futures wrap the thrown exception; walk down to the one the caller should see. */
     private static Throwable unwrap(Throwable error) {
         Throwable cause = error;