diff --git a/CHANGELOG.md b/CHANGELOG.md index c82ba2e..975854f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,9 @@ # Changelog +## 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). + ## 0.3.0 - 2026-09-19 - Async API: `systemOneAsync` mirroring every `systemOne` overload and `models().listAsync()` return `CompletableFuture`s driven by `HttpClient.sendAsync`, so retries back off without holding a thread, honoring the same per-call `RequestOptions` and failing with the same `TypeSafeException` subclasses as the blocking calls (#4). diff --git a/README.md b/README.md index 428e90a..1a7e4d7 100644 --- a/README.md +++ b/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 + +``` + +```properties +logging.level.io.github.premocloud.typesafe=DEBUG +``` + +``` +TRACE io.github.premocloud.typesafe - req-1 -> POST https://api.typesafe.ai/v1/systemone headers={Authorization=***, ...} body={"state":...} +DEBUG io.github.premocloud.typesafe - req-1 <- 200 in 214ms (request req_01a0...) +TRACE io.github.premocloud.typesafe - req-1 <- 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: diff --git a/typesafe-sdk/build.gradle.kts b/typesafe-sdk/build.gradle.kts index 4bbc3fe..ee50943 100644 --- a/typesafe-sdk/build.gradle.kts +++ b/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") } diff --git a/typesafe-sdk/src/main/java/io/github/premocloud/typesafe/Logging.java b/typesafe-sdk/src/main/java/io/github/premocloud/typesafe/Logging.java new file mode 100644 index 0000000..5be400e --- /dev/null +++ b/typesafe-sdk/src/main/java/io/github/premocloud/typesafe/Logging.java @@ -0,0 +1,74 @@ +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.stream.Collectors; + +/** + * What the client logs, tiered as the official SDKs log it. + * + *

{@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. + * + *

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. + * + *

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 SECRET_HEADERS = Set.of( + "authorization", "proxy-authorization", "api-key", "x-api-key", "cookie", "set-cookie"); + + private Logging() { + } + + /** 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 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); + } +} diff --git a/typesafe-sdk/src/main/java/io/github/premocloud/typesafe/TypeSafeClient.java b/typesafe-sdk/src/main/java/io/github/premocloud/typesafe/TypeSafeClient.java index b872429..ac9a4df 100644 --- a/typesafe-sdk/src/main/java/io/github/premocloud/typesafe/TypeSafeClient.java +++ b/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; @@ -25,6 +26,7 @@ import java.util.concurrent.ExecutionException; import java.util.concurrent.ThreadLocalRandom; import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicLong; import java.util.function.Consumer; /** @@ -56,6 +58,9 @@ 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 static final AtomicLong REQUESTS = new AtomicLong(); + private final HttpClient httpClient; private final ObjectMapper objectMapper; private final String apiKey; @@ -192,10 +197,18 @@ private CompletableFuture postAsync(String path, Object body, Class 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 CompletableFuture sendAsync(HttpRequest.Builder template, Class type, RequestOptions options) { + return sendAsync(template, type, options, null); + } + + private CompletableFuture sendAsync(HttpRequest.Builder template, Class type, RequestOptions options, @Nullable String requestBody) { Duration timeout = Objects.requireNonNullElse(options.timeout(), this.timeout); RetryPolicy retryPolicy = options.resolveRetryPolicy(this.retryPolicy); Map headers = new LinkedHashMap<>(defaultHeaders); @@ -208,13 +221,21 @@ private CompletableFuture sendAsync(HttpRequest.Builder template, Class CompletableFuture attemptAsync(HttpRequest.Builder template, Class type, Duration timeout, RetryPolicy retryPolicy, int attempt) { + private CompletableFuture attemptAsync(HttpRequest.Builder template, Class 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> sent = httpClient.sendAsync(httpRequest, HttpResponse.BodyHandlers.ofString()); return sent.>handle((response, error) -> { @@ -223,16 +244,20 @@ private CompletableFuture 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.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.failedFuture(new TypeSafeConnectionException("Connection error: " + ioException.getMessage(), ioException)); @@ -242,14 +267,23 @@ private CompletableFuture 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.failedFuture(TypeSafeApiException.fromResponse(status, response.body(), response.headers())); @@ -260,8 +294,8 @@ private CompletableFuture attemptAsync(HttpRequest.Builder template, Clas } /** Schedules the next attempt on the JDK's shared delayer, so backoff never parks a thread of ours. */ - private CompletableFuture retryAsync(Duration delay, HttpRequest.Builder template, Class type, Duration timeout, RetryPolicy retryPolicy, int attempt) { - return CompletableFuture.supplyAsync(() -> attemptAsync(template, type, timeout, retryPolicy, attempt), + private CompletableFuture retryAsync(Duration delay, HttpRequest.Builder template, Class 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 +326,10 @@ static T blocking(CompletableFuture 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; diff --git a/typesafe-sdk/src/test/java/io/github/premocloud/typesafe/LoggingTest.java b/typesafe-sdk/src/test/java/io/github/premocloud/typesafe/LoggingTest.java new file mode 100644 index 0000000..2c7490c --- /dev/null +++ b/typesafe-sdk/src/test/java/io/github/premocloud/typesafe/LoggingTest.java @@ -0,0 +1,129 @@ +package io.github.premocloud.typesafe; + +import ch.qos.logback.classic.Level; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.spi.ILoggingEvent; +import ch.qos.logback.core.read.ListAppender; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.slf4j.LoggerFactory; + +import java.io.IOException; +import java.time.Duration; +import java.util.List; +import java.util.Map; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; +import static org.junit.jupiter.api.Assertions.assertTrue; + +/** What the client logs, at which level, and what it never puts in a log line. */ +class LoggingTest { + + private static final String API_KEY = "apik-secret-value-1234"; + + private static final String RESPONSE_JSON = """ + {"model": "jev-1.13.0", + "answers": {"q": {"type": "noul", "noul": 0.93}}, + "usage": {"input_tokens": 12, "output_tokens": 3}} + """; + + private StubTypeSafeServer server; + private ListAppender appender; + private ch.qos.logback.classic.Logger logger; + + @BeforeEach + void setUp() throws IOException { + server = new StubTypeSafeServer(); + + LoggerContext context = (LoggerContext) LoggerFactory.getILoggerFactory(); + logger = context.getLogger("io.github.premocloud.typesafe"); + appender = new ListAppender<>(); + appender.setContext(context); + appender.start(); + logger.addAppender(appender); + logger.setLevel(Level.TRACE); + // Capture only: without this the events also reach logback's default console appender and + // every test run prints the request and response bodies. + logger.setAdditive(false); + } + + @AfterEach + void tearDown() { + logger.detachAppender(appender); + logger.setLevel(null); + logger.setAdditive(true); + server.close(); + } + + @Test + void logsOneDebugLinePerRequestWithStatusAndElapsed() { + server.reply(200, RESPONSE_JSON); + + client().systemOne("state", Map.of("q", Noul.of("Yes?"))); + + List debug = messagesAt(Level.DEBUG); + assertEquals(1, debug.size(), debug.toString()); + assertTrue(debug.get(0).matches(".*<- 200 in \\d+ms \\(request .+\\).*"), debug.get(0)); + } + + @Test + void logsTheWireInBothDirectionsAtTrace() { + server.reply(200, RESPONSE_JSON); + + client().systemOne("state", Map.of("q", Noul.of("Yes?"))); + + List trace = messagesAt(Level.TRACE); + assertEquals(2, trace.size(), trace.toString()); + assertTrue(trace.get(0).contains("-> POST"), trace.get(0)); + assertTrue(trace.get(1).contains("<-"), trace.get(1)); + assertTrue(trace.get(1).contains("jev-1.13.0"), "response body is logged: " + trace.get(1)); + } + + @Test + void neverLogsTheApiKey() { + server.reply(200, RESPONSE_JSON); + + client().systemOne("state", Map.of("q", Noul.of("Yes?"))); + + String everything = String.join("\n", messagesAt(null)); + assertFalse(everything.contains(API_KEY), "the key leaked: " + everything); + assertTrue(everything.contains("Authorization=***"), everything); + } + + @Test + void logsARetryLineAtDebug() { + server.reply(429, "{}", Map.of("retry-after-ms", "1")); + server.reply(200, RESPONSE_JSON); + + client().systemOne("state", Map.of("q", Noul.of("Yes?"))); + + assertTrue(messagesAt(Level.DEBUG).stream().anyMatch(m -> m.contains("retrying in")), + messagesAt(Level.DEBUG).toString()); + } + + @Test + void logsNothingAtTheDefaultSpringBootLevel() { + // Java's default root level is INFO, so a stock application must see nothing from this client. + logger.setLevel(Level.INFO); + server.reply(200, RESPONSE_JSON); + + client().systemOne("state", Map.of("q", Noul.of("Yes?"))); + + assertEquals(List.of(), messagesAt(null)); + } + + private TypeSafeClient client() { + return TypeSafeClient.builder().apiKey(API_KEY).baseUrl(server.baseUrl()) + .timeout(Duration.ofSeconds(5)).build(); + } + + /** Formatted messages at one level, or every level when {@code level} is null. */ + private List messagesAt(Level level) { + return appender.list.stream() + .filter(event -> level == null || event.getLevel().equals(level)) + .map(ILoggingEvent::getFormattedMessage) + .toList(); + } +}