diff --git a/README.md b/README.md index e66343a9..0ed42cbc 100644 --- a/README.md +++ b/README.md @@ -97,6 +97,31 @@ call.getOrCreate( > **Note:** When constructing models, always use the **builder pattern** (e.g. `UserRequest.builder().id("id").build()`). > While some generated models expose positional constructors (for example via Lombok's `@AllArgsConstructor`), their parameter order is not part of the public API and may change between releases; using positional constructors is therefore strongly discouraged and may break across SDK updates. +### Logging + +The SDK emits structured log events through [SLF4J](https://www.slf4j.org/) (dependency `org.slf4j:slf4j-api`). Inject your own SLF4J `Logger` via `StreamClientOptions.setLogger(...)`. When no logger is injected the SDK logs to a no-op logger, so nothing is emitted unless you opt in. The SDK never changes the logger's level; that stays entirely under your control through your SLF4J binding. + +```java +org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger("io.getstream"); +var options = new StreamClientOptions().setLogger(logger); +var client = new StreamSDKClient("apiKey", "apiSecret", options); +``` + +Four events are emitted: + +| Event | Level | When | +| ----- | ----- | ---- | +| `client.initialized` | INFO | once, at client construction (SDK name/version and the effective client config) | +| `http.request.sent` | DEBUG | before each request (method, path, query) | +| `http.response.received` | DEBUG | after any response, including 4xx/5xx (status code, body size, duration) | +| `http.request.failed` | ERROR | transport failure only, when no HTTP response was received (error type, message, duration) | + +Redaction is mandatory and cannot be disabled: query values for `api_key`, `api_secret` and `token` are replaced with ``, and the top-level JSON body keys `api_secret`, `token` and `password` are redacted. The events never log request/response headers. + +Request and response bodies are **not** logged by default. Call `StreamClientOptions.setLogBodies(true)` to opt in (secret body keys are still redacted); doing so emits a one-time warning at construction. Do not enable body logging in production unless you accept the risk of logging sensitive payloads. + +> **Deprecated:** the older `HttpLoggingInterceptor` is deprecated in favour of these SLF4J events. It is kept for backward compatibility and now redacts secret headers and secret body keys in its own output. + ## Development To run tests, create the `local.properties` file using the `local.properties.example` and adjust it to have valid API credentials: diff --git a/build.gradle.kts b/build.gradle.kts index 7b9a9062..782d8bb8 100644 --- a/build.gradle.kts +++ b/build.gradle.kts @@ -30,6 +30,7 @@ dependencies { implementation(platform("com.squareup.okhttp3:okhttp-bom:4.12.0")) implementation("com.squareup.okhttp3:okhttp") + implementation("org.slf4j:slf4j-api:2.0.13") implementation("com.fasterxml.jackson.core:jackson-databind:2.18.2") implementation("com.fasterxml.jackson.core:jackson-annotations:2.18.2") implementation("io.jsonwebtoken:jjwt-api:0.12.6") diff --git a/src/main/java/io/getstream/services/framework/HttpLoggingInterceptor.java b/src/main/java/io/getstream/services/framework/HttpLoggingInterceptor.java index 8990467b..072859f2 100644 --- a/src/main/java/io/getstream/services/framework/HttpLoggingInterceptor.java +++ b/src/main/java/io/getstream/services/framework/HttpLoggingInterceptor.java @@ -36,7 +36,13 @@ * *

The format of the logs created by this class should not be considered stable and may change * slightly between releases. If you need a stable logging format, use your own interceptor. + * + * @deprecated Superseded by the SLF4J structured log events emitted by the SDK (inject a logger via + * {@code StreamClientOptions.setLogger}). Kept for backward compatibility. Secret headers, + * secret body keys, and secret URL query values ({@code api_key}/{@code api_secret}/{@code + * token}) are now redacted in its output. */ +@Deprecated public final class HttpLoggingInterceptor implements Interceptor { private static final Charset UTF8 = StandardCharsets.UTF_8; @@ -181,7 +187,7 @@ public Response intercept(Chain chain) throws IOException { "--> " + request.method() + ' ' - + request.url() + + LogRedaction.redactUrl(request.url()) + (connection != null ? " " + connection.protocol() : ""); if (!logHeaders && hasRequestBody) { requestStartMessage += " (" + requestBody.contentLength() + "-byte body)"; @@ -205,7 +211,7 @@ public Response intercept(Chain chain) throws IOException { String name = headers.name(i); // Skip headers from the request body as they are explicitly logged above. if (!"Content-Type".equalsIgnoreCase(name) && !"Content-Length".equalsIgnoreCase(name)) { - logger.log(name + ": " + headers.value(i)); + logger.log(name + ": " + LogRedaction.redactHeaderValue(name, headers.value(i))); } } } @@ -228,7 +234,7 @@ public Response intercept(Chain chain) throws IOException { logger.log("Request body:"); if (isPlaintext(buffer)) { - logger.log(buffer.readString(charset)); + logger.log(LogRedaction.redactJsonBody(buffer.readString(charset))); logger.log( "--> END " + request.method() + " (" + requestBody.contentLength() + "-byte body)"); } else { @@ -259,7 +265,7 @@ public Response intercept(Chain chain) throws IOException { + response.code() + (response.message().isEmpty() ? "" : ' ' + response.message()) + ' ' - + response.request().url() + + LogRedaction.redactUrl(response.request().url()) + " (" + tookMs + "ms" @@ -269,7 +275,10 @@ public Response intercept(Chain chain) throws IOException { if (logHeaders) { Headers headers = response.headers(); for (int i = 0, count = headers.size(); i < count; i++) { - logger.log(headers.name(i) + ": " + headers.value(i)); + logger.log( + headers.name(i) + + ": " + + LogRedaction.redactHeaderValue(headers.name(i), headers.value(i))); } } if (!logResponseBody || response.body() == null) { @@ -298,7 +307,7 @@ public Response intercept(Chain chain) throws IOException { if (contentLength != 0) { logger.log("Response body:"); - logger.log(buffer.clone().readString(charset)); + logger.log(LogRedaction.redactJsonBody(buffer.clone().readString(charset))); } logger.log("<-- END HTTP (" + buffer.size() + "-byte body)"); diff --git a/src/main/java/io/getstream/services/framework/LogRedaction.java b/src/main/java/io/getstream/services/framework/LogRedaction.java new file mode 100644 index 00000000..43a04c95 --- /dev/null +++ b/src/main/java/io/getstream/services/framework/LogRedaction.java @@ -0,0 +1,70 @@ +package io.getstream.services.framework; + +import com.fasterxml.jackson.databind.ObjectMapper; +import com.fasterxml.jackson.databind.node.ObjectNode; +import java.util.Set; +import okhttp3.HttpUrl; + +/** Redaction helpers for the SDK's structured log events. Shallow by design. */ +final class LogRedaction { + static final String REDACTED = ""; + private static final Set QUERY_PARAMS = Set.of("api_key", "api_secret", "token"); + private static final Set BODY_KEYS = Set.of("api_secret", "token", "password"); + private static final ObjectMapper MAPPER = new ObjectMapper(); + + private LogRedaction() {} + + static String redactQuery(HttpUrl url) { + if (url.querySize() == 0) return ""; + var b = new StringBuilder(); + for (int i = 0; i < url.querySize(); i++) { + if (i > 0) b.append('&'); + String name = url.queryParameterName(i); + String value = + QUERY_PARAMS.contains(name.toLowerCase()) ? REDACTED : url.queryParameterValue(i); + b.append(name).append('=').append(value); + } + return b.toString(); + } + + /** + * Full URL as a string with secret query values redacted, scheme/host/path preserved. Used by the + * deprecated {@link HttpLoggingInterceptor}, whose response-summary line logs the final request + * URL after a downstream interceptor may have appended {@code api_key}. + */ + static String redactUrl(HttpUrl url) { + String base = url.newBuilder().query(null).build().toString(); + String query = redactQuery(url); + return query.isEmpty() ? base : base + "?" + query; + } + + static boolean isSecretHeader(String name) { + String n = name.toLowerCase(); + return n.equals("authorization") + || n.endsWith("-token") + || n.endsWith("-secret") + || n.endsWith("-key"); + } + + static String redactHeaderValue(String name, String value) { + return isSecretHeader(name) ? REDACTED : value; + } + + static String redactJsonBody(String body) { + if (body == null || body.isEmpty()) return body; + try { + var node = MAPPER.readTree(body); + if (!(node instanceof ObjectNode obj)) return body; + boolean changed = false; + for (String key : BODY_KEYS) { + if (obj.has(key)) { + obj.put(key, REDACTED); + changed = true; + } + } + return changed ? MAPPER.writeValueAsString(obj) : body; + } catch (Exception e) { + return body; + } + } +} diff --git a/src/main/java/io/getstream/services/framework/StreamClientOptions.java b/src/main/java/io/getstream/services/framework/StreamClientOptions.java index 9c08f7d7..e344a10b 100644 --- a/src/main/java/io/getstream/services/framework/StreamClientOptions.java +++ b/src/main/java/io/getstream/services/framework/StreamClientOptions.java @@ -4,6 +4,8 @@ import okhttp3.OkHttpClient; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; +import org.slf4j.Logger; +import org.slf4j.helpers.NOPLogger; /** * Tunables for the SDK's HTTP transport / connection pool. Per CHA-2956. Defaults: 5 conns/host, @@ -21,6 +23,8 @@ public class StreamClientOptions { @NotNull private Duration connectTimeout = DEFAULT_CONNECT_TIMEOUT; @NotNull private Duration requestTimeout = DEFAULT_REQUEST_TIMEOUT; @Nullable private OkHttpClient httpClient; + @Nullable private Logger logger; + private boolean logBodies = false; public StreamClientOptions setMaxConnsPerHost(int n) { if (n <= 0) throw new IllegalArgumentException("maxConnsPerHost must be > 0, got " + n); @@ -55,6 +59,24 @@ public StreamClientOptions setHttpClient(@Nullable OkHttpClient client) { return this; } + /** + * Inject an SLF4J {@link Logger} for the SDK's structured log events. When unset, the SDK logs to + * a no-op logger. The SDK never sets the logger's level. + */ + public StreamClientOptions setLogger(@Nullable Logger logger) { + this.logger = logger; + return this; + } + + /** + * Opt in to logging HTTP request/response bodies on the debug events. Secret body keys are still + * redacted. Off by default; enabling it emits a one-time warning at client construction. + */ + public StreamClientOptions setLogBodies(boolean logBodies) { + this.logBodies = logBodies; + return this; + } + public int getMaxConnsPerHost() { return maxConnsPerHost; } @@ -82,4 +104,18 @@ public OkHttpClient getHttpClient() { public boolean hasUserHttpClient() { return httpClient != null; } + + @Nullable + public Logger getLogger() { + return logger; + } + + @NotNull + public Logger getLoggerOrNop() { + return logger != null ? logger : NOPLogger.NOP_LOGGER; + } + + public boolean getLogBodies() { + return logBodies; + } } diff --git a/src/main/java/io/getstream/services/framework/StreamHTTPClient.java b/src/main/java/io/getstream/services/framework/StreamHTTPClient.java index 4cbecdc3..64cdd6d7 100644 --- a/src/main/java/io/getstream/services/framework/StreamHTTPClient.java +++ b/src/main/java/io/getstream/services/framework/StreamHTTPClient.java @@ -14,7 +14,6 @@ import java.time.Duration; import java.util.*; import java.util.concurrent.TimeUnit; -import java.util.logging.Logger; import javax.crypto.spec.SecretKeySpec; import okhttp3.ConnectionPool; import okhttp3.Dispatcher; @@ -22,10 +21,9 @@ import okhttp3.OkHttpClient; import okhttp3.Request; import org.jetbrains.annotations.NotNull; +import org.slf4j.Logger; public class StreamHTTPClient { - private static final Logger LOG = Logger.getLogger(StreamHTTPClient.class.getName()); - public static final String API_KEY_PROP_NAME = "io.getstream.apiKey"; public static final String API_SECRET_PROP_NAME = "io.getstream.apiSecret"; public static final String API_TIMEOUT_PROP_NAME = "io.getstream.timeout"; @@ -98,6 +96,14 @@ public StreamHTTPClient() { } public StreamHTTPClient(Properties properties) throws IllegalArgumentException { + this(properties, new StreamClientOptions()); + } + + public StreamHTTPClient(Properties properties, @NotNull StreamClientOptions options) + throws IllegalArgumentException { + // Set options before reading env/properties so env overrides (timeout, connection max-age) + // fold into them and the caller's injected logger is used for the client.initialized event. + this.options = options; readPropertiesAndEnv(properties); if (apiKey == null || apiKey.isEmpty()) { @@ -152,6 +158,22 @@ public String getBaseUrl() { return baseUrl; } + // Why: construction-time / test-support only (points a client at MockWebServer). Package-private + // to keep it off the public API; not safe for concurrent post-construction mutation. + void setBaseUrl(@NotNull String baseUrl) { + this.baseUrl = baseUrl; + } + + /** The SLF4J logger for structured events (a no-op logger when none was injected). */ + @NotNull + public Logger getLogger() { + return options.getLoggerOrNop(); + } + + public boolean getLogBodies() { + return options.getLogBodies(); + } + private void setCredetials(@NotNull String apiKey, @NotNull String apiSecret) { this.apiKey = apiKey; this.apiSecret = apiSecret; @@ -176,17 +198,26 @@ private OkHttpClient.Builder defaultHttpClientBuilder() { } private void logEffectiveConfig() { - if (options.hasUserHttpClient()) { - LOG.info("connection pool: user_http_client=true (4 knobs not applied)"); - } else { - LOG.info( - String.format( - "connection pool: max_conns_per_host=%d idle_timeout=%s connect_timeout=%s" - + " request_timeout=%s user_http_client=false", - options.getMaxConnsPerHost(), - options.getIdleTimeout(), - options.getConnectTimeout(), - options.getRequestTimeout())); + Logger logger = getLogger(); + logger.info( + "client.initialized stream.sdk.name=stream-sdk-java stream.sdk.version={}" + + " stream.client.max_conns_per_host={} stream.client.idle_timeout_seconds={}" + + " stream.client.connect_timeout_seconds={} stream.client.request_timeout_seconds={}" + + " stream.client.gzip_enabled={} stream.client.user_http_client={}" + + " stream.client.log_bodies={}", + sdkVersion, + options.getMaxConnsPerHost(), + options.getIdleTimeout().toSeconds(), + options.getConnectTimeout().toSeconds(), + options.getRequestTimeout().toSeconds(), + true, + options.hasUserHttpClient(), + options.getLogBodies()); + if (options.getLogBodies()) { + logger.warn( + "HTTP request/response bodies will be logged. Auth headers and known-secret fields are" + + " still redacted, but other sensitive data (messages, PII) may appear in logs." + + " Disable for production."); } } @@ -242,10 +273,12 @@ private void readPropertiesAndEnv(Properties properties) { } } + @SuppressWarnings("deprecation") private @NotNull HttpLoggingInterceptor.Level getLogLevel() { return HttpLoggingInterceptor.Level.valueOf(logLevel); } + @SuppressWarnings("deprecation") private OkHttpClient buildHTTPClient(String jwtToken, OkHttpClient.Builder httpClient) { httpClient.interceptors().clear(); diff --git a/src/main/java/io/getstream/services/framework/StreamRequest.java b/src/main/java/io/getstream/services/framework/StreamRequest.java index b7ec902e..804e149e 100644 --- a/src/main/java/io/getstream/services/framework/StreamRequest.java +++ b/src/main/java/io/getstream/services/framework/StreamRequest.java @@ -13,6 +13,7 @@ import io.getstream.models.framework.StreamResponse; import java.io.File; import java.io.IOException; +import java.nio.charset.StandardCharsets; import java.time.Duration; import java.util.Date; import java.util.List; @@ -20,6 +21,8 @@ import java.util.concurrent.TimeUnit; import okhttp3.*; import org.jetbrains.annotations.NotNull; +import org.slf4j.Logger; +import org.slf4j.helpers.NOPLogger; public class StreamRequest { private final OkHttpClient client; @@ -27,6 +30,36 @@ public class StreamRequest { private final ObjectMapper objectMapper; private final TypeReference typeReference; private Duration callTimeoutOverride; + private Logger logger = NOPLogger.NOP_LOGGER; + private boolean logBodies = false; + // Serialized JSON request body captured at construction so logRequestSent can emit it (redacted) + // without re-reading the OkHttp RequestBody. Null for GET/DELETE/multipart uploads. + private String requestBodyJson; + + /** + * Preferred constructor: derives the transport, base URL, logger and log-bodies flag from {@code + * client}, so the request emits the SDK's structured log events. + */ + public StreamRequest( + StreamHTTPClient client, + String method, + String path, + Object jRequest, + Map pathParams, + TypeReference typeReference) + throws StreamException { + this( + client.getHttpClient(), + client.getObjectMapper(), + client.getBaseUrl(), + method, + path, + jRequest, + pathParams, + typeReference); + this.logger = client.getLogger(); + this.logBodies = client.getLogBodies(); + } public StreamRequest( OkHttpClient client, @@ -56,7 +89,9 @@ public StreamRequest( } else if (jRequest instanceof UploadChannelImageRequest) { rawBody = createMultipartBody((UploadChannelImageRequest) jRequest); } else { - rawBody = RequestBody.create(objectMapper.writeValueAsBytes(jRequest)); + byte[] bodyBytes = objectMapper.writeValueAsBytes(jRequest); + this.requestBodyJson = new String(bodyBytes, StandardCharsets.UTF_8); + rawBody = RequestBody.create(bodyBytes); } request = new Request.Builder() @@ -250,17 +285,82 @@ public StreamResponse execute() throws StreamException { // callTimeout for this single dispatch. call.timeout().timeout(callTimeoutOverride.toNanos(), TimeUnit.NANOSECONDS); } + logRequestSent(); + long startNanos = System.nanoTime(); Response response; try { response = call.execute(); } catch (IOException e) { - // IO failure: classify and re-throw as StreamTransportException. - throw StreamTransportException.fromIOException(e); + // Transport failure: no HTTP response was received. Classify, log ERROR, then re-throw. + StreamTransportException transportException = StreamTransportException.fromIOException(e); + logger.error( + "http.request.failed http.request.method={} url.path={} url.query={} error.type={}" + + " error.message={} duration_ms={}", + request.method(), + request.url().encodedPath(), + LogRedaction.redactQuery(request.url()), + transportException.getErrorType(), + e.getMessage(), + elapsedMs(startNanos)); + throw transportException; } + logResponseReceived(response, elapsedMs(startNanos)); return this.parseResponse(response); } + private static long elapsedMs(long startNanos) { + return (System.nanoTime() - startNanos) / 1_000_000; + } + + private void logRequestSent() { + if (logBodies && requestBodyJson != null) { + logger.debug( + "http.request.sent http.request.method={} url.path={} url.query={} http.request.body={}", + request.method(), + request.url().encodedPath(), + LogRedaction.redactQuery(request.url()), + LogRedaction.redactJsonBody(requestBodyJson)); + } else { + logger.debug( + "http.request.sent http.request.method={} url.path={} url.query={}", + request.method(), + request.url().encodedPath(), + LogRedaction.redactQuery(request.url())); + } + } + + private void logResponseReceived(Response response, long durationMs) { + long bodySize = response.body() != null ? response.body().contentLength() : -1; + if (logBodies) { + String body; + try { + // peekBody copies up to the limit without consuming the real body that parseResponse reads. + body = LogRedaction.redactJsonBody(response.peekBody(1_048_576).string()); + } catch (IOException e) { + body = ""; + } + logger.debug( + "http.response.received http.request.method={} url.path={} http.response.status_code={}" + + " http.response.body.size={} duration_ms={} http.response.body={}", + request.method(), + request.url().encodedPath(), + response.code(), + bodySize, + durationMs, + body); + } else { + logger.debug( + "http.response.received http.request.method={} url.path={} http.response.status_code={}" + + " http.response.body.size={} duration_ms={}", + request.method(), + request.url().encodedPath(), + response.code(), + bodySize, + durationMs); + } + } + private StreamResponse parseResponse(okhttp3.Response response) throws StreamException { if (!response.isSuccessful()) { // 4xx/5xx → StreamApiException (StreamRateLimitException for 429). diff --git a/src/test/java/io/getstream/StreamHTTPClientTest.java b/src/test/java/io/getstream/StreamHTTPClientTest.java index 786bff38..76e14519 100644 --- a/src/test/java/io/getstream/StreamHTTPClientTest.java +++ b/src/test/java/io/getstream/StreamHTTPClientTest.java @@ -17,10 +17,6 @@ import java.util.List; import java.util.Map; import java.util.concurrent.TimeUnit; -import java.util.logging.Handler; -import java.util.logging.Level; -import java.util.logging.LogRecord; -import java.util.logging.Logger; import okhttp3.ConnectionPool; import okhttp3.OkHttpClient; import org.junit.jupiter.api.BeforeAll; @@ -301,57 +297,80 @@ void testEscapeHatchViaOptionsBypassesKnobs() { built.interceptors().isEmpty(), "SDK still adds its interceptors to user-supplied client"); } - private static class CapturingHandler extends Handler { + // Records the SLF4J events emitted at construction (client.initialized replaced the old + // java.util.logging "connection pool:" line in CHA-2957); inject via StreamClientOptions. + static final class RecordingLogger extends org.slf4j.helpers.LegacyAbstractLogger { final List messages = new ArrayList<>(); @Override - public void publish(LogRecord r) { - if (r.getLevel().intValue() >= Level.INFO.intValue()) messages.add(r.getMessage()); + protected void handleNormalizedLoggingCall( + org.slf4j.event.Level level, + org.slf4j.Marker marker, + String messagePattern, + Object[] arguments, + Throwable throwable) { + messages.add(org.slf4j.helpers.MessageFormatter.basicArrayFormat(messagePattern, arguments)); } @Override - public void flush() {} + protected String getFullyQualifiedCallerName() { + return null; + } @Override - public void close() throws SecurityException {} - } + public boolean isTraceEnabled() { + return true; + } - private String captureLastPoolLog(Runnable construct) { - Logger jul = Logger.getLogger("io.getstream.services.framework.StreamHTTPClient"); - CapturingHandler h = new CapturingHandler(); - jul.addHandler(h); - try { - construct.run(); - return h.messages.stream() - .filter(m -> m.startsWith("connection pool:")) - .reduce((a, b) -> b) - .orElseThrow(); - } finally { - jul.removeHandler(h); + @Override + public boolean isDebugEnabled() { + return true; + } + + @Override + public boolean isInfoEnabled() { + return true; } + + @Override + public boolean isWarnEnabled() { + return true; + } + + @Override + public boolean isErrorEnabled() { + return true; + } + } + + private static String lastClientInitialized(RecordingLogger rec) { + return rec.messages.stream() + .filter(m -> m.startsWith("client.initialized")) + .reduce((a, b) -> b) + .orElseThrow(); } @Test void testInfoLogOnConstructionWithDefaults() { - String got = - captureLastPoolLog( - () -> new StreamHTTPClient("apiKey", "012345678901234567890123456789ab")); - assertTrue(got.contains("max_conns_per_host=5"), got); - assertTrue(got.contains("idle_timeout=PT55S"), got); - assertTrue(got.contains("connect_timeout=PT10S"), got); - assertTrue(got.contains("request_timeout=PT30S"), got); - assertTrue(got.contains("user_http_client=false"), got); + RecordingLogger rec = new RecordingLogger(); + new StreamHTTPClient( + "apiKey", "012345678901234567890123456789ab", new StreamClientOptions().setLogger(rec)); + String got = lastClientInitialized(rec); + assertTrue(got.contains("stream.client.max_conns_per_host=5"), got); + assertTrue(got.contains("stream.client.idle_timeout_seconds=55"), got); + assertTrue(got.contains("stream.client.connect_timeout_seconds=10"), got); + assertTrue(got.contains("stream.client.request_timeout_seconds=30"), got); + assertTrue(got.contains("stream.client.user_http_client=false"), got); } @Test void testInfoLogOnConstructionWithUserHttpClient() { + RecordingLogger rec = new RecordingLogger(); StreamClientOptions opts = - new StreamClientOptions().setHttpClient(new OkHttpClient.Builder().build()); - String got = - captureLastPoolLog( - () -> new StreamHTTPClient("apiKey", "012345678901234567890123456789ab", opts)); - assertTrue(got.contains("user_http_client=true"), got); - assertTrue(got.contains("4 knobs not applied"), got); + new StreamClientOptions().setHttpClient(new OkHttpClient.Builder().build()).setLogger(rec); + new StreamHTTPClient("apiKey", "012345678901234567890123456789ab", opts); + String got = lastClientInitialized(rec); + assertTrue(got.contains("stream.client.user_http_client=true"), got); } @Test @@ -413,10 +432,12 @@ void testConnectionMaxAgeEnvPropertyStillOverridesIdleTimeout() { System.setProperty(StreamHTTPClient.API_KEY_PROP_NAME, "apiKey"); System.setProperty(StreamHTTPClient.API_SECRET_PROP_NAME, "012345678901234567890123456789ab"); - String got = captureLastPoolLog(() -> new StreamHTTPClient(System.getProperties())); + RecordingLogger rec = new RecordingLogger(); + new StreamHTTPClient(System.getProperties(), new StreamClientOptions().setLogger(rec)); + String got = lastClientInitialized(rec); assertTrue( - got.contains("idle_timeout=PT2M3S"), - "STREAM_API_CONNECTION_MAX_AGE must drive the idle timeout (123s = PT2M3S), got: " + got); + got.contains("stream.client.idle_timeout_seconds=123"), + "STREAM_API_CONNECTION_MAX_AGE must drive the idle timeout (123s), got: " + got); } finally { restoreProperty(StreamHTTPClient.API_CONNECTION_MAX_AGE_PROP_NAME, prevMaxAge); restoreProperty(StreamHTTPClient.API_KEY_PROP_NAME, prevKey); diff --git a/src/test/java/io/getstream/services/framework/LoggingTest.java b/src/test/java/io/getstream/services/framework/LoggingTest.java new file mode 100644 index 00000000..04e98f9a --- /dev/null +++ b/src/test/java/io/getstream/services/framework/LoggingTest.java @@ -0,0 +1,237 @@ +package io.getstream.services.framework; + +import static org.junit.jupiter.api.Assertions.*; + +import com.fasterxml.jackson.core.type.TypeReference; +import java.util.ArrayList; +import java.util.List; +import java.util.Map; +import okhttp3.HttpUrl; +import okhttp3.OkHttpClient; +import okhttp3.Request; +import okhttp3.Response; +import okhttp3.mockwebserver.MockResponse; +import okhttp3.mockwebserver.MockWebServer; +import okhttp3.mockwebserver.SocketPolicy; +import org.junit.jupiter.api.*; +import org.slf4j.event.Level; +import org.slf4j.helpers.LegacyAbstractLogger; +import org.slf4j.helpers.MessageFormatter; + +// Lives in io.getstream.services.framework (not io.getstream) so it can reach the package-private +// StreamHTTPClient.setBaseUrl and LogRedaction without any public test-only API surface. +public class LoggingTest { + static final class RecordingLogger extends LegacyAbstractLogger { + record Entry(Level level, String message) {} + + final List entries = new ArrayList<>(); + + @Override + protected void handleNormalizedLoggingCall( + Level level, org.slf4j.Marker m, String template, Object[] args, Throwable t) { + entries.add(new Entry(level, MessageFormatter.basicArrayFormat(template, args))); + } + + @Override + protected String getFullyQualifiedCallerName() { + return null; + } + + @Override + public boolean isTraceEnabled() { + return true; + } + + @Override + public boolean isDebugEnabled() { + return true; + } + + @Override + public boolean isInfoEnabled() { + return true; + } + + @Override + public boolean isWarnEnabled() { + return true; + } + + @Override + public boolean isErrorEnabled() { + return true; + } + + List named(String event) { + return entries.stream().filter(e -> e.message().startsWith(event)).toList(); + } + } + + private MockWebServer server; + private RecordingLogger log; + + @BeforeEach + void setUp() throws Exception { + server = new MockWebServer(); + server.start(); + log = new RecordingLogger(); + } + + @AfterEach + void tearDown() throws Exception { + server.shutdown(); + } + + private StreamHTTPClient client(boolean logBodies) { + // HS256 needs a >=32-byte secret (see StreamErrorHandlingTest); "secret" would throw WeakKey. + var options = new StreamClientOptions().setLogger(log).setLogBodies(logBodies); + var c = new StreamHTTPClient("key", "012345678901234567890123456789ab", options); + c.setBaseUrl(server.url("/").toString()); + return c; + } + + private void get(StreamHTTPClient c) throws Exception { + getPath(c, "/api/v2/app"); + } + + private void getPath(StreamHTTPClient c, String path) throws Exception { + new StreamRequest>(c, "GET", path, null, null, new TypeReference<>() {}) + .execute(); + } + + @Test + void clientInitializedOnceWithSchema() { + client(false); + var inits = log.named("client.initialized"); + assertEquals(1, inits.size()); + String m = inits.get(0).message(); + // sdk.name is a fixed constant; version is present but its value depends on version.properties. + assertTrue(m.contains("stream.sdk.name=stream-sdk-java"), m); + assertTrue(m.contains("stream.sdk.version="), m); + // Pool/timeout knobs equal the StreamClientOptions defaults for a default-options client. + assertTrue( + m.contains( + "stream.client.max_conns_per_host=" + StreamClientOptions.DEFAULT_MAX_CONNS_PER_HOST), + m); + assertTrue( + m.contains( + "stream.client.idle_timeout_seconds=" + + StreamClientOptions.DEFAULT_IDLE_TIMEOUT.toSeconds()), + m); + assertTrue( + m.contains( + "stream.client.connect_timeout_seconds=" + + StreamClientOptions.DEFAULT_CONNECT_TIMEOUT.toSeconds()), + m); + assertTrue( + m.contains( + "stream.client.request_timeout_seconds=" + + StreamClientOptions.DEFAULT_REQUEST_TIMEOUT.toSeconds()), + m); + assertTrue(m.contains("stream.client.gzip_enabled=true"), m); + assertTrue(m.contains("stream.client.user_http_client=false"), m); + assertTrue(m.contains("stream.client.log_bodies=false"), m); + } + + @Test + void sentAndReceivedOnSuccess() throws Exception { + server.enqueue( + new MockResponse() + .setResponseCode(200) + .setHeader("Content-Type", "application/json") + .setBody("{}")); + get(client(false)); + assertEquals(1, log.named("http.request.sent").size()); + var received = log.named("http.response.received"); + assertEquals(1, received.size()); + assertTrue(received.get(0).message().contains("http.response.status_code=200")); + } + + @Test + void errorStatusIsReceivedNotFailed() { + server.enqueue( + new MockResponse() + .setResponseCode(500) + .setHeader("Content-Type", "application/json") + .setBody("{\"code\":1,\"message\":\"boom\"}")); + assertThrows(Exception.class, () -> get(client(false))); + assertEquals(1, log.named("http.response.received").size()); + assertEquals(0, log.named("http.request.failed").size()); + } + + @Test + void transportFailureEmitsFailed() { + server.enqueue(new MockResponse().setSocketPolicy(SocketPolicy.DISCONNECT_AT_START)); + assertThrows(Exception.class, () -> get(client(false))); + var failed = log.named("http.request.failed"); + assertEquals(1, failed.size()); + assertEquals(Level.ERROR, failed.get(0).level()); + assertTrue(failed.get(0).message().contains("error.type=")); + } + + @Test + void queryRedaction() throws Exception { + // A real, non-empty query carrying a secret proves redactQuery actually transforms it. The old + // test passed a null query, so redactQuery short-circuited on querySize()==0 and never ran. + server.enqueue( + new MockResponse() + .setResponseCode(200) + .setHeader("Content-Type", "application/json") + .setBody("{}")); + getPath(client(false), "/api/v2/app?token=SECRETVALUE"); + var sent = log.named("http.request.sent"); + assertEquals(1, sent.size()); + assertTrue(sent.get(0).message().contains("url.query=token="), sent.get(0).message()); + for (var e : log.entries) { + assertFalse(e.message().contains("SECRETVALUE"), () -> "token leaked: " + e.message()); + } + } + + @Test + @SuppressWarnings("deprecation") + void deprecatedInterceptorRedactsApiKeyInUrl() throws Exception { + // Reproduces the real leak class: the auth interceptor appends api_key downstream, so the + // response's request URL carries it. Both URL log sites (request-start, response-summary) must + // redact regardless of interceptor ordering, so we put api_key straight on the request URL. + server.enqueue( + new MockResponse() + .setResponseCode(200) + .setHeader("Content-Type", "application/json") + .setBody("{}")); + var lines = new ArrayList(); + var interceptor = + new HttpLoggingInterceptor(lines::add).setLevel(HttpLoggingInterceptor.Level.BASIC); + var okhttp = new OkHttpClient.Builder().addInterceptor(interceptor).build(); + HttpUrl url = + server.url("/api/v2/app").newBuilder().addQueryParameter("api_key", "SECRETKEY").build(); + try (Response resp = okhttp.newCall(new Request.Builder().url(url).build()).execute()) { + assertEquals(200, resp.code()); + } + String all = String.join("\n", lines); + assertTrue(all.contains("api_key="), () -> "expected redacted api_key:\n" + all); + assertFalse(all.contains("SECRETKEY"), () -> "api_key leaked:\n" + all); + } + + @Test + void logBodiesOptInAndWarn() throws Exception { + // The secret VALUE must not share a substring with the key name: shallow redaction keeps the + // key "token" (only its value is replaced), so a value like "tok" would still be reported as + // present via the key. Use a distinctive value and assert on it plus the marker. + server.enqueue( + new MockResponse() + .setResponseCode(200) + .setHeader("Content-Type", "application/json") + .setBody("{\"token\":\"supersecret\",\"keep\":\"v\"}")); + var c = client(true); + var warns = + log.entries.stream() + .filter(e -> e.level() == Level.WARN && e.message().contains("bodies will be logged")) + .toList(); + assertEquals(1, warns.size()); + get(c); + var received = log.named("http.response.received"); + assertTrue(received.get(0).message().contains("http.response.body=")); + assertFalse(received.get(0).message().contains("supersecret")); + assertTrue(received.get(0).message().contains("")); + } +}