From f0f873d06dc8205a9e76d282f9e2660aefe2850f Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Thu, 2 Jan 2025 15:32:33 -0800 Subject: [PATCH 1/8] simplify HttpLoggingPolicy --- .../core/checkstyle-suppressions.xml | 1 + sdk/clientcore/core/spotbugs-exclude.xml | 6 +- .../core/http/models/HttpHeaderName.java | 10 - .../core/http/models/HttpLogOptions.java | 60 +- .../core/http/models/RequestOptions.java | 2 +- .../core/http/pipeline/HttpLoggingPolicy.java | 403 ++++++------ .../core/http/pipeline/HttpRequestLogger.java | 35 -- .../http/pipeline/HttpResponseLogger.java | 39 -- .../core/http/pipeline/HttpRetryPolicy.java | 2 +- .../core/implementation/util/LoggingKeys.java | 17 +- .../io/clientcore/core/util/ClientLogger.java | 36 ++ .../RequestOptionsJavaDocCodeSnippets.java | 2 +- .../models/BinaryDataJavaDocCodeSnippet.java | 2 +- .../core/util/ClientLoggerTests.java | 48 +- .../core/util/HttpLoggingPolicyTests.java | 593 ++++++++++++++++++ 15 files changed, 862 insertions(+), 394 deletions(-) delete mode 100644 sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRequestLogger.java delete mode 100644 sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpResponseLogger.java create mode 100644 sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java diff --git a/sdk/clientcore/core/checkstyle-suppressions.xml b/sdk/clientcore/core/checkstyle-suppressions.xml index 54063f5ebb41..b9e79ae1d076 100644 --- a/sdk/clientcore/core/checkstyle-suppressions.xml +++ b/sdk/clientcore/core/checkstyle-suppressions.xml @@ -36,4 +36,5 @@ + diff --git a/sdk/clientcore/core/spotbugs-exclude.xml b/sdk/clientcore/core/spotbugs-exclude.xml index 211af17f9483..c7ba52b2cb6f 100644 --- a/sdk/clientcore/core/spotbugs-exclude.xml +++ b/sdk/clientcore/core/spotbugs-exclude.xml @@ -123,6 +123,7 @@ + @@ -238,7 +239,10 @@ - + + + + diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/HttpHeaderName.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/HttpHeaderName.java index 00fd98c56913..361cd07bae42 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/HttpHeaderName.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/HttpHeaderName.java @@ -191,16 +191,6 @@ public boolean equals(Object obj) { */ public static final HttpHeaderName CACHE_CONTROL = fromString("Cache-Control"); - /** - * {@code client-request-id} - */ - public static final HttpHeaderName REQUEST_ID = fromString("Request-Id"); - - /** - * {@code client-request-id} - */ - public static final HttpHeaderName CLIENT_REQUEST_ID = fromString("client-request-id"); - /** * {@code traceparent} */ diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/HttpLogOptions.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/HttpLogOptions.java index dcb58b49d391..1814586f3779 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/HttpLogOptions.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/HttpLogOptions.java @@ -3,8 +3,6 @@ package io.clientcore.core.http.models; -import io.clientcore.core.http.pipeline.HttpRequestLogger; -import io.clientcore.core.http.pipeline.HttpResponseLogger; import io.clientcore.core.util.configuration.Configuration; import java.util.Arrays; @@ -23,15 +21,13 @@ public final class HttpLogOptions { private HttpLogDetailLevel logLevel; private Set allowedHeaderNames; private Set allowedQueryParamNames; - private HttpRequestLogger requestLogger; - private HttpResponseLogger responseLogger; private static final List DEFAULT_HEADERS_ALLOWLIST = Arrays.asList(HttpHeaderName.TRACEPARENT, HttpHeaderName.ACCEPT, HttpHeaderName.CACHE_CONTROL, HttpHeaderName.CONNECTION, HttpHeaderName.CONTENT_LENGTH, HttpHeaderName.CONTENT_TYPE, HttpHeaderName.DATE, HttpHeaderName.ETAG, HttpHeaderName.EXPIRES, HttpHeaderName.IF_MATCH, HttpHeaderName.IF_MODIFIED_SINCE, HttpHeaderName.IF_NONE_MATCH, HttpHeaderName.IF_UNMODIFIED_SINCE, HttpHeaderName.LAST_MODIFIED, - HttpHeaderName.PRAGMA, HttpHeaderName.CLIENT_REQUEST_ID, HttpHeaderName.RETRY_AFTER, HttpHeaderName.SERVER, - HttpHeaderName.TRANSFER_ENCODING, HttpHeaderName.USER_AGENT, HttpHeaderName.WWW_AUTHENTICATE); + HttpHeaderName.PRAGMA, HttpHeaderName.RETRY_AFTER, HttpHeaderName.SERVER, HttpHeaderName.TRANSFER_ENCODING, + HttpHeaderName.USER_AGENT, HttpHeaderName.WWW_AUTHENTICATE); private static final List DEFAULT_QUERY_PARAMS_ALLOWLIST = Collections.singletonList("api-version"); @@ -149,58 +145,6 @@ public HttpLogOptions addAllowedQueryParamName(final String allowedQueryParamNam return this; } - /** - * Gets the {@link HttpRequestLogger} that will be used to log HTTP requests. - * - *

A default {@link HttpRequestLogger} will be used if one isn't supplied. - * - * @return The {@link HttpRequestLogger} that will be used to log HTTP requests. - */ - public HttpRequestLogger getRequestLogger() { - return requestLogger; - } - - /** - * Sets the {@link HttpRequestLogger} that will be used to log HTTP requests. - * - *

A default {@link HttpRequestLogger} will be used if one isn't supplied. - * - * @param requestLogger The {@link HttpRequestLogger} that will be used to log HTTP requests. - * - * @return The updated HttpLogOptions object. - */ - public HttpLogOptions setRequestLogger(HttpRequestLogger requestLogger) { - this.requestLogger = requestLogger; - - return this; - } - - /** - * Gets the {@link HttpResponseLogger} that will be used to log HTTP responses. - * - *

A default {@link HttpResponseLogger} will be used if one isn't supplied. - * - * @return The {@link HttpResponseLogger} that will be used to log HTTP responses. - */ - public HttpResponseLogger getResponseLogger() { - return responseLogger; - } - - /** - * Sets the {@link HttpResponseLogger} that will be used to log HTTP responses. - * - *

A default {@link HttpResponseLogger} will be used if one isn't supplied. - * - * @param responseLogger The {@link HttpResponseLogger} that will be used to log HTTP responses. - * - * @return The updated HttpLogOptions object. - */ - public HttpLogOptions setResponseLogger(HttpResponseLogger responseLogger) { - this.responseLogger = responseLogger; - - return this; - } - /** * The level of detail to log on HTTP messages. */ diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/RequestOptions.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/RequestOptions.java index 5dbce1218273..f44b9e12711e 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/RequestOptions.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/RequestOptions.java @@ -103,7 +103,7 @@ * // may already be set if request is created from a client * .setUri("https://petstore.example.com/pet") * .setHttpMethod(HttpMethod.POST) - * .setBody(BinaryData.fromString(requestBodyData)) + * .setBody(requestBodyData) * .getHeaders().set(HttpHeaderName.CONTENT_TYPE, "application/json")); * * diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java index 0d73e13225aa..f7948dbee76d 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java @@ -19,15 +19,12 @@ import java.io.IOException; import java.net.URI; -import java.time.Duration; -import java.util.Collections; import java.util.Locale; import java.util.Map; import java.util.Set; +import java.util.function.Consumer; import java.util.stream.Collectors; -import static io.clientcore.core.http.models.ContentType.APPLICATION_OCTET_STREAM; -import static io.clientcore.core.http.models.HttpHeaderName.CLIENT_REQUEST_ID; import static io.clientcore.core.http.models.HttpHeaderName.TRACEPARENT; import static io.clientcore.core.implementation.util.ImplUtils.isNullOrEmpty; @@ -35,17 +32,22 @@ * The pipeline policy that handles logging of HTTP requests and responses. */ public class HttpLoggingPolicy implements HttpPipelinePolicy { + private static final HttpLogOptions DEFAULT_HTTP_LOG_OPTIONS = new HttpLogOptions(); private static final int MAX_BODY_LOG_SIZE = 1024 * 16; private static final String REDACTED_PLACEHOLDER = "REDACTED"; private static final ClientLogger LOGGER = new ClientLogger(HttpLoggingPolicy.class); private final HttpLogOptions.HttpLogDetailLevel httpLogDetailLevel; private final Set allowedHeaderNames; + private final Set alwaysAllowedHeaders = Set.of(TRACEPARENT); private final Set allowedQueryParameterNames; - private final HttpRequestLogger requestLogger; - private final HttpResponseLogger responseLogger; - private static final String REQUEST_LOG_MESSAGE = "HTTP request"; - private static final String RESPONSE_LOG_MESSAGE = "HTTP response"; + private static final String HTTP_REQUEST_EVENT_NAME = "http.request"; + private static final String HTTP_RESPONSE_EVENT_NAME = "http.response"; + + // request log level is low (verbose) since almost all request details are also + // captured on the response log. + private static final ClientLogger.LogLevel HTTP_REQUEST_LOG_LEVEL = ClientLogger.LogLevel.VERBOSE; + private static final ClientLogger.LogLevel HTTP_RESPONSE_LOG_LEVEL = ClientLogger.LogLevel.INFORMATIONAL; /** * Creates an HttpLoggingPolicy with the given log configurations. @@ -53,26 +55,13 @@ public class HttpLoggingPolicy implements HttpPipelinePolicy { * @param httpLogOptions The HTTP logging configuration options. */ public HttpLoggingPolicy(HttpLogOptions httpLogOptions) { - if (httpLogOptions == null) { - this.httpLogDetailLevel = HttpLogOptions.HttpLogDetailLevel.NONE; - this.allowedHeaderNames = Collections.emptySet(); - this.allowedQueryParameterNames = Collections.emptySet(); - this.requestLogger = new DefaultHttpRequestLogger(); - this.responseLogger = new DefaultHttpResponseLogger(); - } else { - this.httpLogDetailLevel = httpLogOptions.getLogLevel(); - this.allowedHeaderNames = httpLogOptions.getAllowedHeaderNames(); - this.allowedQueryParameterNames = httpLogOptions.getAllowedQueryParamNames() - .stream() - .map(queryParamName -> queryParamName.toLowerCase(Locale.ROOT)) - .collect(Collectors.toSet()); - this.requestLogger = (httpLogOptions.getRequestLogger() == null) - ? new DefaultHttpRequestLogger() - : httpLogOptions.getRequestLogger(); - this.responseLogger = (httpLogOptions.getResponseLogger() == null) - ? new DefaultHttpResponseLogger() - : httpLogOptions.getResponseLogger(); - } + HttpLogOptions logOptionsToUse = httpLogOptions == null ? DEFAULT_HTTP_LOG_OPTIONS : httpLogOptions; + this.httpLogDetailLevel = logOptionsToUse.getLogLevel(); + this.allowedHeaderNames = logOptionsToUse.getAllowedHeaderNames(); + this.allowedQueryParameterNames = logOptionsToUse.getAllowedQueryParamNames() + .stream() + .map(queryParamName -> queryParamName.toLowerCase(Locale.ROOT)) + .collect(Collectors.toSet()); } @Override @@ -82,162 +71,177 @@ public Response process(HttpRequest httpRequest, HttpPipelineNextPolicy next) return next.process(); } - ClientLogger logger = null; - - if (httpRequest.getRequestOptions() != null) { - logger = httpRequest.getRequestOptions().getLogger(); - } - - if (logger == null) { - logger = LOGGER; - } + ClientLogger logger = getLogger(httpRequest); final long startNs = System.nanoTime(); + final String redactedUrl = getRedactedUri(httpRequest.getUri(), allowedQueryParameterNames); + final int tryCount = HttpRequestAccessHelper.getRetryCount(httpRequest); + final long requestContentLength = httpRequest.getBody() == null + ? 0 + : getContentLength(logger, httpRequest.getBody(), httpRequest.getHeaders()); - requestLogger.logRequest(logger, httpRequest); + logRequest(logger, httpRequest, startNs, requestContentLength, redactedUrl, tryCount); try { Response response = next.process(); - if (response != null) { - response = responseLogger.logResponse(logger, response, Duration.ofNanos(System.nanoTime() - startNs)); + if (response == null) { + LOGGER.atError() + .addKeyValue(LoggingKeys.HTTP_METHOD_KEY, httpRequest.getHttpMethod()) + .addKeyValue(LoggingKeys.URI_KEY, redactedUrl) + .log( + "HTTP response is null and no exception is thrown. Please report it to the client library maintainers."); + + return null; } - return response; + return logResponse(logger, response, startNs, requestContentLength, redactedUrl, tryCount); } catch (RuntimeException e) { - createBasicLoggingContext(logger, ClientLogger.LogLevel.WARNING, httpRequest).log("HTTP FAILED", e); - - throw LOGGER.logThrowableAsError(e); + throw logException(logger, httpRequest, null, e, startNs, null, requestContentLength, redactedUrl, + tryCount); } } - private ClientLogger.LoggingEventBuilder createBasicLoggingContext(ClientLogger logger, ClientLogger.LogLevel level, - HttpRequest request) { - ClientLogger.LoggingEventBuilder log = logger.atLevel(level); - if (LOGGER.canLogAtLevel(level) && request != null) { - if (allowedHeaderNames.contains(CLIENT_REQUEST_ID)) { - String clientRequestId = request.getHeaders().getValue(CLIENT_REQUEST_ID); - if (clientRequestId != null) { - log.addKeyValue(CLIENT_REQUEST_ID.getCaseInsensitiveName(), clientRequestId); - } - } - - if (allowedHeaderNames.contains(TRACEPARENT)) { - String traceparent = request.getHeaders().getValue(TRACEPARENT); - if (traceparent != null) { - log.addKeyValue(TRACEPARENT.getCaseInsensitiveName(), traceparent); - } - } + private ClientLogger getLogger(HttpRequest request) { + if (request.getRequestOptions() != null) { + return request.getRequestOptions().getLogger(); } - return log; + return LOGGER; } - private final class DefaultHttpRequestLogger implements HttpRequestLogger { - @Override - public void logRequest(ClientLogger logger, HttpRequest request) { - final ClientLogger.LogLevel logLevel = getLogLevel(request); - - if (logger.canLogAtLevel(logLevel)) { - log(logLevel, logger, request); - } + private void logRequest(ClientLogger logger, HttpRequest request, long startNanoTime, long requestContentLength, + String redactedUrl, int tryCount) { + ClientLogger.LoggingEventBuilder logBuilder = logger.atLevel(HTTP_REQUEST_LOG_LEVEL); + if (!logBuilder.isEnabled() || httpLogDetailLevel == HttpLogOptions.HttpLogDetailLevel.NONE) { + return; } - private void log(ClientLogger.LogLevel logLevel, ClientLogger logger, HttpRequest request) { - ClientLogger.LoggingEventBuilder logBuilder = getLogBuilder(logLevel, logger); - - if (httpLogDetailLevel.shouldLogUri()) { - logBuilder.addKeyValue(LoggingKeys.HTTP_METHOD_KEY, request.getHttpMethod()) - .addKeyValue(LoggingKeys.URI_KEY, getRedactedUri(request.getUri(), allowedQueryParameterNames)); - - logBuilder.addKeyValue(LoggingKeys.TRY_COUNT_KEY, getRequestRetryCount(request)); + logBuilder.setEventName(HTTP_REQUEST_EVENT_NAME) + .addKeyValue(LoggingKeys.HTTP_METHOD_KEY, request.getHttpMethod()) + .addKeyValue(LoggingKeys.URI_KEY, redactedUrl) + .addKeyValue(LoggingKeys.TRY_COUNT_KEY, tryCount) + .addKeyValue(LoggingKeys.REQUEST_CONTENT_LENGTH_KEY, requestContentLength); + + addHeadersToLogMessage(request.getHeaders(), logBuilder); + + if (httpLogDetailLevel.shouldLogBody() && canLogBody(request.getBody())) { + String content; + try { + content = request.getBody().toString(); + } catch (RuntimeException e) { + // we'll log exception at the appropriate level. + throw logException(logger, request, null, e, startNanoTime, null, requestContentLength, redactedUrl, + tryCount); } - if (httpLogDetailLevel.shouldLogHeaders() && logger.canLogAtLevel(ClientLogger.LogLevel.INFORMATIONAL)) { - addHeadersToLogMessage(allowedHeaderNames, request.getHeaders(), logBuilder); - } - - if (request.getBody() == null) { - logBuilder.addKeyValue(LoggingKeys.CONTENT_LENGTH_KEY, 0).log(REQUEST_LOG_MESSAGE); - return; - } - - String contentType = request.getHeaders().getValue(HttpHeaderName.CONTENT_TYPE); - long contentLength = getContentLength(logger, request.getHeaders()); - - logBuilder.addKeyValue(LoggingKeys.CONTENT_LENGTH_KEY, contentLength); - - if (httpLogDetailLevel.shouldLogBody() && shouldBodyBeLogged(contentType, contentLength)) { - logBody(request, logBuilder); - return; - } - - logBuilder.log(REQUEST_LOG_MESSAGE); + logBuilder.addKeyValue(LoggingKeys.BODY_KEY, content); } - } - private void logBody(HttpRequest request, ClientLogger.LoggingEventBuilder logBuilder) { - logBuilder.addKeyValue(LoggingKeys.BODY_KEY, request.getBody().toString()).log(REQUEST_LOG_MESSAGE); + logBuilder.log(); } - private final class DefaultHttpResponseLogger implements HttpResponseLogger { - private void logHeaders(ClientLogger logger, Response response, - ClientLogger.LoggingEventBuilder logBuilder) { - if (httpLogDetailLevel.shouldLogHeaders() && logger.canLogAtLevel(ClientLogger.LogLevel.INFORMATIONAL)) { - addHeadersToLogMessage(allowedHeaderNames, response.getHeaders(), logBuilder); - } + private Response logResponse(ClientLogger logger, Response response, long startNanoTime, + long requestContentLength, String redactedUrl, int tryCount) { + ClientLogger.LoggingEventBuilder logBuilder = logger.atLevel(HTTP_RESPONSE_LOG_LEVEL); + if (httpLogDetailLevel == HttpLogOptions.HttpLogDetailLevel.NONE) { + return response; } - private void logUri(Response response, Duration duration, ClientLogger.LoggingEventBuilder logBuilder) { - if (httpLogDetailLevel.shouldLogUri()) { - logBuilder.addKeyValue(LoggingKeys.STATUS_CODE_KEY, response.getStatusCode()) - .addKeyValue(LoggingKeys.URI_KEY, - getRedactedUri(response.getRequest().getUri(), allowedQueryParameterNames)) - .addKeyValue(LoggingKeys.DURATION_MS_KEY, duration.toMillis()); - } + long timeToHeadersNanoTime = System.nanoTime(); + + // response may be disabled, but we still need to log the exception if an exception occurs during stream reading. + if (logBuilder.isEnabled()) { + logBuilder.setEventName(HTTP_RESPONSE_EVENT_NAME) + .addKeyValue(LoggingKeys.HTTP_METHOD_KEY, response.getRequest().getHttpMethod()) + .addKeyValue(LoggingKeys.TRY_COUNT_KEY, tryCount) + .addKeyValue(LoggingKeys.URI_KEY, redactedUrl) + .addKeyValue(LoggingKeys.TIME_TO_HEADERS_MS, getDurationMs(startNanoTime, timeToHeadersNanoTime)) + .addKeyValue(LoggingKeys.STATUS_CODE_KEY, response.getStatusCode()) + .addKeyValue(LoggingKeys.REQUEST_CONTENT_LENGTH_KEY, requestContentLength) + .addKeyValue(LoggingKeys.RESPONSE_CONTENT_LENGTH_KEY, + getContentLength(logger, response.getBody(), response.getHeaders())); + + addHeadersToLogMessage(response.getHeaders(), logBuilder); } - private void logContentLength(Response response, ClientLogger.LoggingEventBuilder logBuilder) { - String contentLengthString = response.getHeaders().getValue(HttpHeaderName.CONTENT_LENGTH); - - if (!isNullOrEmpty(contentLengthString)) { - logBuilder.addKeyValue(LoggingKeys.CONTENT_LENGTH_KEY, contentLengthString); - } + if (httpLogDetailLevel.shouldLogBody() && canLogBody(response.getBody())) { + return new LoggingHttpResponse<>(response, content -> { + if (logBuilder.isEnabled()) { + logBuilder.addKeyValue(LoggingKeys.BODY_KEY, content) + .addKeyValue(LoggingKeys.DURATION_MS_KEY, getDurationMs(startNanoTime, System.nanoTime())) + .log(); + } + }, throwable -> logException(logger, response.getRequest(), response, throwable, startNanoTime, + timeToHeadersNanoTime, requestContentLength, redactedUrl, tryCount)); } - @Override - public Response logResponse(ClientLogger logger, Response response, Duration duration) { - final ClientLogger.LogLevel logLevel = getLogLevel(response); - - if (!logger.canLogAtLevel(logLevel)) { - return response; - } - - ClientLogger.LoggingEventBuilder logBuilder = getLogBuilder(logLevel, logger); + if (logBuilder.isEnabled()) { + logBuilder.addKeyValue(LoggingKeys.DURATION_MS_KEY, getDurationMs(startNanoTime, System.nanoTime())).log(); + } - logContentLength(response, logBuilder); - logUri(response, duration, logBuilder); - logHeaders(logger, response, logBuilder); + return response; + } - if (httpLogDetailLevel.shouldLogBody()) { - String contentTypeHeader = response.getHeaders().getValue(HttpHeaderName.CONTENT_TYPE); - long contentLength = getContentLength(logger, response.getHeaders()); + private T logException(ClientLogger logger, HttpRequest request, Response response, + T throwable, long startNanoTime, Long timeToHeadersNanoTime, long requestContentLength, String redactedUrl, + int tryCount) { + ClientLogger.LoggingEventBuilder logBuilder = logger.atLevel(ClientLogger.LogLevel.WARNING); + if (!logBuilder.isEnabled() || httpLogDetailLevel == HttpLogOptions.HttpLogDetailLevel.NONE) { + return throwable; + } - if (shouldBodyBeLogged(contentTypeHeader, contentLength)) { - return new LoggingHttpResponse<>(response, logBuilder); - } + logBuilder.setEventName(HTTP_RESPONSE_EVENT_NAME) + .addKeyValue(LoggingKeys.HTTP_METHOD_KEY, request.getHttpMethod()) + .addKeyValue(LoggingKeys.TRY_COUNT_KEY, tryCount) + .addKeyValue(LoggingKeys.URI_KEY, redactedUrl) + .addKeyValue(LoggingKeys.REQUEST_CONTENT_LENGTH_KEY, requestContentLength) + .addKeyValue(LoggingKeys.DURATION_MS_KEY, getDurationMs(startNanoTime, System.nanoTime())); + + if (response != null) { + addHeadersToLogMessage(response.getHeaders(), logBuilder); + logBuilder + .addKeyValue(LoggingKeys.RESPONSE_CONTENT_LENGTH_KEY, + getContentLength(logger, response.getBody(), response.getHeaders())) + .addKeyValue(LoggingKeys.STATUS_CODE_KEY, response.getStatusCode()); + + if (timeToHeadersNanoTime != null) { + logBuilder.addKeyValue(LoggingKeys.TIME_TO_HEADERS_MS, + getDurationMs(startNanoTime, timeToHeadersNanoTime)); } + } - logBuilder.log(RESPONSE_LOG_MESSAGE); + return logBuilder.log(null, throwable); + } - return response; - } + private double getDurationMs(long startNs, long endNs) { + return (endNs - startNs) / 1_000_000.0; + } + + /** + * Determines if the request or response body should be logged. + * + *

The request or response body is logged if the body is replayable, content length is known, + * isn't empty, and is less than 16KB in size.

+ * + * @param data The request or response body. + * @return A flag indicating if the request or response body should be logged. + */ + private static boolean canLogBody(BinaryData data) { + // TODO: limolkova - we might want to filter out binary data, but + // if somebody enabled logging it - why not log it? + return data != null + && data.isReplayable() + && data.getLength() != null + && data.getLength() > 0 + && data.getLength() < MAX_BODY_LOG_SIZE; } - /* + /** * Generates the redacted URI for logging. * * @param uri URI where the request is being sent. + * @param allowedQueryParameterNames Query parameters that are allowed to be logged. * @return A URI with query parameters redacted based on configurations in this policy. */ private static String getRedactedUri(URI uri, Set allowedQueryParameterNames) { @@ -280,30 +284,45 @@ private static String getRedactedUri(URI uri, Set allowedQueryParameterN return uriBuilder.toString(); } - /* + /** * Adds HTTP headers into the StringBuilder that is generating the log message. * * @param headers HTTP headers on the request or response. - * @param sb StringBuilder that is generating the log message. - * @param logLevel Log level the environment is configured to use. + * @param logBuilder Log message builder. */ - private static void addHeadersToLogMessage(Set allowedHeaderNames, HttpHeaders headers, - ClientLogger.LoggingEventBuilder logBuilder) { - for (HttpHeader header : headers) { - HttpHeaderName headerName = header.getName(); - String headerValue = allowedHeaderNames.contains(headerName) ? header.getValue() : REDACTED_PLACEHOLDER; - logBuilder.addKeyValue(headerName.toString(), headerValue); + private void addHeadersToLogMessage(HttpHeaders headers, ClientLogger.LoggingEventBuilder logBuilder) { + if (httpLogDetailLevel.shouldLogHeaders()) { + for (HttpHeader header : headers) { + HttpHeaderName headerName = header.getName(); + String headerValue = allowedHeaderNames.contains(headerName) ? header.getValue() : REDACTED_PLACEHOLDER; + logBuilder.addKeyValue(headerName.toString(), headerValue); + } + } else { + for (HttpHeaderName headerName : alwaysAllowedHeaders) { + String headerValue = headers.getValue(headerName); + if (headerValue != null) { + logBuilder.addKeyValue(headerName.toString(), headerValue); + } + } } } - /* - * Attempts to retrieve and parse the Content-Length header into a numeric representation. + /** + * Attempts to get request or response body content length. + *

+ * If the body length is known, it will be returned. + * Otherwise, the method parses Content-Length header. * * @param logger Logger used to log a warning if the Content-Length header is an invalid number. + * @param body The request or response body object. * @param headers HTTP headers that are checked for containing Content-Length. - * @return + * @return The numeric value of the Content-Length header or 0 if the header is not present or invalid. */ - private static long getContentLength(ClientLogger logger, HttpHeaders headers) { + private static long getContentLength(ClientLogger logger, BinaryData body, HttpHeaders headers) { + if (body != null && body.getLength() != null) { + return body.getLength(); + } + long contentLength = 0; String contentLengthString = headers.getValue(HttpHeaderName.CONTENT_LENGTH); @@ -323,74 +342,46 @@ private static long getContentLength(ClientLogger logger, HttpHeaders headers) { return contentLength; } - /** - * Determines if the request or response body should be logged. - * - *

The request or response body is logged if the Content-Type is not "application/octet-stream" and the body - * isn't empty and is less than 16KB in size.

- * - * @param contentTypeHeader Content-Type header value. - * @param contentLength Content-Length header represented as a numeric. - * @return A flag indicating if the request or response body should be logged. - */ - private static boolean shouldBodyBeLogged(String contentTypeHeader, long contentLength) { - return !APPLICATION_OCTET_STREAM.equalsIgnoreCase(contentTypeHeader) - && contentLength != 0 - && contentLength < MAX_BODY_LOG_SIZE; - } - - /** - * Gets the request retry count to include in logging. - */ - private static int getRequestRetryCount(HttpRequest request) { - return HttpRequestAccessHelper.getRetryCount(request); - } - - private static ClientLogger.LoggingEventBuilder getLogBuilder(ClientLogger.LogLevel logLevel, ClientLogger logger) { - switch (logLevel) { - case ERROR: - return logger.atError(); - - case WARNING: - return logger.atWarning(); - - case INFORMATIONAL: - return logger.atInfo(); - - case VERBOSE: - default: - return logger.atVerbose(); - } - } - private static final class LoggingHttpResponse extends HttpResponse { - private final ClientLogger.LoggingEventBuilder logBuilder; + private boolean logged = false; + private final Consumer onContent; + private final Consumer onException; - private LoggingHttpResponse(Response actualResponse, ClientLogger.LoggingEventBuilder logBuilder) { + private LoggingHttpResponse(Response actualResponse, Consumer onContent, + Consumer onException) { super(actualResponse.getRequest(), actualResponse.getStatusCode(), actualResponse.getHeaders(), actualResponse.getValue()); HttpResponseAccessHelper.setBody(this, actualResponse.getBody()); - this.logBuilder = logBuilder; + this.onContent = onContent; + this.onException = onException; } @Override public BinaryData getBody() { - BinaryData content = super.getBody(); - - doLog(content.toString()); + if (logged) { + return super.getBody(); + } - return content; + logged = true; + try { + BinaryData content = super.getBody(); + onContent.accept(content.toString()); + return content; + } catch (RuntimeException e) { + // we'll log exception at the appropriate level. + onException.accept(e); + throw e; + } } @Override public void close() throws IOException { + if (!logged) { + getBody(); + } super.close(); } - - private void doLog(String body) { - logBuilder.addKeyValue("body", body).log(RESPONSE_LOG_MESSAGE); - } } } diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRequestLogger.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRequestLogger.java deleted file mode 100644 index 34747e51d904..000000000000 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRequestLogger.java +++ /dev/null @@ -1,35 +0,0 @@ -// Copyright (c) Microsoft Corporation. All rights reserved. -// Licensed under the MIT License. - -package io.clientcore.core.http.pipeline; - -import io.clientcore.core.http.models.HttpRequest; -import io.clientcore.core.util.ClientLogger; - -/** - * Manages logging HTTP requests in {@link HttpLoggingPolicy}. - */ -@FunctionalInterface -public interface HttpRequestLogger { - /** - * Gets the {@link ClientLogger.LogLevel} used to log the HTTP request. - *

- * By default, this will return {@link ClientLogger.LogLevel#INFORMATIONAL}. - * - * @param request The request being logged. - * @return The {@link ClientLogger.LogLevel} used to log the HTTP request. - */ - default ClientLogger.LogLevel getLogLevel(HttpRequest request) { - return ClientLogger.LogLevel.INFORMATIONAL; - } - - /** - * Logs the HTTP request. - *

- * To get the {@link ClientLogger.LogLevel} used to log the HTTP request use {@link #getLogLevel(HttpRequest)}. - * - * @param logger The {@link ClientLogger} used to log the HTTP request. - * @param request The request being logged. - */ - void logRequest(ClientLogger logger, HttpRequest request); -} diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpResponseLogger.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpResponseLogger.java deleted file mode 100644 index 8bde0ee15c64..000000000000 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpResponseLogger.java +++ /dev/null @@ -1,39 +0,0 @@ -// Copyright (c) Microsoft Corporation. All rights reserved. -// Licensed under the MIT License. - -package io.clientcore.core.http.pipeline; - -import io.clientcore.core.http.models.Response; -import io.clientcore.core.util.ClientLogger; - -import java.time.Duration; - -/** - * Manages logging HTTP responses in {@link HttpLoggingPolicy}. - */ -@FunctionalInterface -public interface HttpResponseLogger { - /** - * Gets the {@link ClientLogger.LogLevel} used to log the HTTP response. - *

- * By default, this will return {@link ClientLogger.LogLevel#INFORMATIONAL}. - * - * @param response The response being logged. - * @return The {@link ClientLogger.LogLevel} used to log the HTTP response. - */ - default ClientLogger.LogLevel getLogLevel(Response response) { - return ClientLogger.LogLevel.INFORMATIONAL; - } - - /** - * Logs the HTTP response. - *

- * To get the {@link ClientLogger.LogLevel} used to log the HTTP response use {@link #getLogLevel(Response)} . - * - * @param logger The {@link ClientLogger} used to log the response. - * @param response The response being logged. - * @param duration The duration of the HTTP call. - * @return The HTTP response that was logged. - */ - Response logResponse(ClientLogger logger, Response response, Duration duration); -} diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRetryPolicy.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRetryPolicy.java index 922ac8ce3090..0146627161d1 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRetryPolicy.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRetryPolicy.java @@ -136,7 +136,7 @@ private Duration getWellKnownRetryDelay(HttpHeaders responseHeaders, int tryCoun private Response attempt(final HttpRequest httpRequest, final HttpPipelineNextPolicy next, final int tryCount, final List suppressed) { - HttpRequestAccessHelper.setRetryCount(httpRequest, tryCount + 1); + HttpRequestAccessHelper.setRetryCount(httpRequest, tryCount); Response response; diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/util/LoggingKeys.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/util/LoggingKeys.java index 1b980ee23a69..1a6136c4cdd6 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/util/LoggingKeys.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/util/LoggingKeys.java @@ -25,8 +25,18 @@ private LoggingKeys() { */ public static final String TRY_COUNT_KEY = "tryCount"; + /** + * Key representing time from request start to the moment response (headers and response code) were received in milliseconds, + * the value should be a number. + *

+ * Depending on the implementation and content type, this time may include time to receive the body. + */ + public static final String TIME_TO_HEADERS_MS = "timeToHeadersMs"; + /** * Key representing duration of call in milliseconds, the value should be a number. + *

+ * This time can */ public static final String DURATION_MS_KEY = "durationMs"; @@ -43,7 +53,12 @@ private LoggingKeys() { /** * Key representing request body content length. */ - public static final String CONTENT_LENGTH_KEY = "contentLength"; + public static final String REQUEST_CONTENT_LENGTH_KEY = "requestContentLength"; + + /** + * Key representing response body content length. + */ + public static final String RESPONSE_CONTENT_LENGTH_KEY = "responseContentLength"; /** * Key representing request body. The value should be populated conditionally diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/util/ClientLogger.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/util/ClientLogger.java index 32d45120433b..442b5053dad4 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/util/ClientLogger.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/util/ClientLogger.java @@ -287,6 +287,7 @@ public static final class LoggingEventBuilder { private final Map globalPairs; private final boolean isEnabled; private Map keyValuePairs; + private String eventName; /** * Creates {@code LoggingEventBuilder} for provided level and {@link ClientLogger}. @@ -308,6 +309,15 @@ private LoggingEventBuilder(Slf4jLoggerShim logger, LogLevel level, Map valueSupplie return this; } + /** + * Sets the event name for the current log event. The event name is used to query all logs + * that describe the same event. It must not contain any dynamic parts. + * + * @param eventName The name of the event. + * @return The updated {@code LoggingEventBuilder} object. + */ + public LoggingEventBuilder setEventName(String eventName) { + this.eventName = eventName; + return this; + } + + /** + * Logs event annotated with context. + */ + public void log() { + if (this.isEnabled) { + logger.performLogging(level, getMessageWithContext(null), null); + } + } + /** * Logs message annotated with context. * @@ -444,6 +475,7 @@ public T log(String message, T throwable) { if (this.isEnabled) { boolean isDebugEnabled = logger.canLogAtLevel(LogLevel.VERBOSE); if (throwable != null) { + addKeyValueInternal("exception.type", throwable.getClass().getCanonicalName()); addKeyValueInternal("exception.message", throwable.getMessage()); if (isDebugEnabled) { StringBuilder stackTrace = new StringBuilder(); @@ -480,6 +512,10 @@ private String getMessageWithContext(String message) { } } + if (eventName != null) { + jsonWriter.writeStringField("event.name", eventName); + } + jsonWriter.writeEndObject().flush(); return outputStream.toString(StandardCharsets.UTF_8); diff --git a/sdk/clientcore/core/src/samples/java/io/clientcore/core/http/models/RequestOptionsJavaDocCodeSnippets.java b/sdk/clientcore/core/src/samples/java/io/clientcore/core/http/models/RequestOptionsJavaDocCodeSnippets.java index 7bf16da65c01..834c9645e9f2 100644 --- a/sdk/clientcore/core/src/samples/java/io/clientcore/core/http/models/RequestOptionsJavaDocCodeSnippets.java +++ b/sdk/clientcore/core/src/samples/java/io/clientcore/core/http/models/RequestOptionsJavaDocCodeSnippets.java @@ -60,7 +60,7 @@ public RequestOptions setJsonRequestBodyInRequestOptions() { // may already be set if request is created from a client .setUri("https://petstore.example.com/pet") .setHttpMethod(HttpMethod.POST) - .setBody(BinaryData.fromString(requestBodyData)) + .setBody(requestBodyData) .getHeaders().set(HttpHeaderName.CONTENT_TYPE, "application/json")); // END: io.clientcore.core.http.rest.requestoptions.postrequest return options; diff --git a/sdk/clientcore/core/src/samples/java/io/clientcore/core/models/BinaryDataJavaDocCodeSnippet.java b/sdk/clientcore/core/src/samples/java/io/clientcore/core/models/BinaryDataJavaDocCodeSnippet.java index 7685a365aec2..f727a2f34161 100644 --- a/sdk/clientcore/core/src/samples/java/io/clientcore/core/models/BinaryDataJavaDocCodeSnippet.java +++ b/sdk/clientcore/core/src/samples/java/io/clientcore/core/models/BinaryDataJavaDocCodeSnippet.java @@ -342,7 +342,7 @@ private void streamConsumer(InputStream stream) { // no-op } - public static class MyJsonSerializer implements JsonSerializer { + public static class MyJsonSerializer extends JsonSerializer { private static final ClientLogger LOGGER = new ClientLogger(MyJsonSerializer.class); @Override diff --git a/sdk/clientcore/core/src/test/java/io/clientcore/core/util/ClientLoggerTests.java b/sdk/clientcore/core/src/test/java/io/clientcore/core/util/ClientLoggerTests.java index b5755e48becd..80718c864420 100644 --- a/sdk/clientcore/core/src/test/java/io/clientcore/core/util/ClientLoggerTests.java +++ b/sdk/clientcore/core/src/test/java/io/clientcore/core/util/ClientLoggerTests.java @@ -588,6 +588,7 @@ public void logWithContextWithThrowableInArgs(LogLevel logLevelToConfigure) { expectedMessage.put("message", "Don't format strings when writing logs, please!"); expectedMessage.put("connectionId", "foo"); expectedMessage.put("linkName", "bar"); + expectedMessage.put("exception.type", runtimeException.getClass().getCanonicalName()); expectedMessage.put("exception.message", exceptionMessage); if (logLevelToConfigure.equals(LogLevel.VERBOSE)) { @@ -617,6 +618,7 @@ public void logWithContextMessageSupplierAndThrowableInArgs(LogLevel logLevelToC expectedMessage.put("message", "hello world"); expectedMessage.put("connectionId", "foo"); expectedMessage.put("linkName", "bar"); + expectedMessage.put("exception.type", ioException.getClass().getCanonicalName()); expectedMessage.put("exception.message", exceptionMessage); if (logLevelToConfigure.equals(LogLevel.VERBOSE)) { @@ -646,6 +648,7 @@ public void logWithContextWithThrowableInArgsAndEscaping(LogLevel logLevelToConf expectedMessage.put("message", "hello \"world\""); expectedMessage.put("connection\tId", "foo"); expectedMessage.put("linkName", "\rbar"); + expectedMessage.put("exception.type", runtimeException.getClass().getCanonicalName()); expectedMessage.put("exception.message", exceptionMessage); if (logLevelToConfigure.equals(LogLevel.VERBOSE)) { @@ -676,6 +679,7 @@ public void logWithContextRuntimeException(LogLevel logLevelToConfigure) { expectedMessage.put("message", ""); expectedMessage.put("connectionId", "foo"); expectedMessage.put("linkName", "bar"); + expectedMessage.put("exception.type", runtimeException.getClass().getCanonicalName()); expectedMessage.put("exception.message", exceptionMessage); if (logLevelToConfigure.equals(LogLevel.VERBOSE)) { @@ -706,6 +710,7 @@ public void logWithContextThrowable(LogLevel logLevelToConfigure) { expectedMessage.put("message", ""); expectedMessage.put("connectionId", "foo"); expectedMessage.put("linkName", "bar"); + expectedMessage.put("exception.type", ioException.getClass().getCanonicalName()); expectedMessage.put("exception.message", exceptionMessage); if (logLevelToConfigure.equals(LogLevel.VERBOSE)) { @@ -725,6 +730,7 @@ public void logSupplierShouldLogExceptionOnVerboseLevel() { Map expectedMessage = new HashMap<>(); expectedMessage.put("message", message); + expectedMessage.put("exception.type", exception.getClass().getCanonicalName()); expectedMessage.put("exception.message", null); expectedMessage.put("exception.stacktrace", expectedStackTrace); @@ -769,26 +775,7 @@ private void logMessage(ClientLogger logger, LogLevel logLevel, String logMessag return; } - switch (logLevel) { - case VERBOSE: - logger.atVerbose().log(logMessage, runtimeException); - break; - - case INFORMATIONAL: - logger.atInfo().log(logMessage, runtimeException); - break; - - case WARNING: - logger.atWarning().log(logMessage, runtimeException); - break; - - case ERROR: - logger.atError().log(logMessage, runtimeException); - break; - - default: - break; - } + logger.atLevel(logLevel).log(logMessage, runtimeException); } private void logMessage(ClientLogger logger, LogLevel logLevel, String logMessage) { @@ -796,26 +783,7 @@ private void logMessage(ClientLogger logger, LogLevel logLevel, String logMessag return; } - switch (logLevel) { - case VERBOSE: - logger.atVerbose().log(logMessage); - break; - - case INFORMATIONAL: - logger.atInfo().log(logMessage); - break; - - case WARNING: - logger.atWarning().log(logMessage); - break; - - case ERROR: - logger.atError().log(logMessage); - break; - - default: - break; - } + logger.atLevel(logLevel).log(logMessage); } private static IllegalStateException createIllegalStateException(String message) { diff --git a/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java b/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java new file mode 100644 index 000000000000..bdc429666679 --- /dev/null +++ b/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java @@ -0,0 +1,593 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +// we want to access package-private ClientLogger constructor +package io.clientcore.core.util; + +import io.clientcore.core.http.MockHttpResponse; +import io.clientcore.core.http.models.HttpHeader; +import io.clientcore.core.http.models.HttpHeaderName; +import io.clientcore.core.http.models.HttpHeaders; +import io.clientcore.core.http.models.HttpLogOptions; +import io.clientcore.core.http.models.HttpMethod; +import io.clientcore.core.http.models.HttpRequest; +import io.clientcore.core.http.models.RequestOptions; +import io.clientcore.core.http.models.Response; +import io.clientcore.core.http.pipeline.HttpLoggingPolicy; +import io.clientcore.core.http.pipeline.HttpPipeline; +import io.clientcore.core.http.pipeline.HttpPipelineBuilder; +import io.clientcore.core.implementation.AccessibleByteArrayOutputStream; +import io.clientcore.core.implementation.http.HttpRequestAccessHelper; +import io.clientcore.core.implementation.util.DefaultLogger; +import io.clientcore.core.serialization.json.JsonOptions; +import io.clientcore.core.serialization.json.JsonProviders; +import io.clientcore.core.serialization.json.JsonReader; +import io.clientcore.core.util.binarydata.BinaryData; +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.parallel.Execution; +import org.junit.jupiter.api.parallel.ExecutionMode; +import org.junit.jupiter.params.ParameterizedTest; +import org.junit.jupiter.params.provider.Arguments; +import org.junit.jupiter.params.provider.MethodSource; + +import java.io.IOException; +import java.io.InputStream; +import java.io.PrintStream; +import java.io.UncheckedIOException; +import java.nio.charset.StandardCharsets; +import java.util.Collections; +import java.util.HashSet; +import java.util.List; +import java.util.Map; +import java.util.Set; +import java.util.function.Function; +import java.util.stream.Stream; + +import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertInstanceOf; +import static org.junit.jupiter.api.Assertions.assertNull; +import static org.junit.jupiter.api.Assertions.assertThrows; + +@Execution(ExecutionMode.SAME_THREAD) +public class HttpLoggingPolicyTests { + private static final String URI = "https://example.com?param=value&api-version=42"; + private static final String REDACTED_URI = "https://example.com?param=REDACTED&api-version=42"; + private static final Set DEFAULT_ALLOWED_QUERY_PARAMS = new HttpLogOptions().getAllowedQueryParamNames(); + private static final Set DEFAULT_ALLOWED_HEADERS = new HttpLogOptions().getAllowedHeaderNames(); + private static final HttpHeaderName CUSTOM_REQUEST_ID = HttpHeaderName.fromString("custom-request-id"); + + private final AccessibleByteArrayOutputStream logCaptureStream; + + public HttpLoggingPolicyTests() { + this.logCaptureStream = new AccessibleByteArrayOutputStream(); + } + + @ParameterizedTest + @MethodSource("disabledHttpLoggingSource") + public void testDisabledHttpLogging(ClientLogger.LogLevel logLevel, HttpLogOptions.HttpLogDetailLevel httpLogLevel) + throws IOException { + ClientLogger logger = setupLogLevelAndGetLogger(logLevel); + + HttpPipeline pipeline = createPipeline(new HttpLogOptions().setLogLevel(httpLogLevel)); + HttpRequest request = new HttpRequest(HttpMethod.GET, URI); + request.setRequestOptions(new RequestOptions().setLogger(logger)); + + pipeline.send(request).close(); + + assertEquals(0, parseLogMessages().size()); + } + + public static Stream disabledHttpLoggingSource() { + return Stream.of(Arguments.of(ClientLogger.LogLevel.VERBOSE, HttpLogOptions.HttpLogDetailLevel.NONE), + Arguments.of(ClientLogger.LogLevel.WARNING, HttpLogOptions.HttpLogDetailLevel.BASIC), + Arguments.of(ClientLogger.LogLevel.WARNING, HttpLogOptions.HttpLogDetailLevel.HEADERS), + Arguments.of(ClientLogger.LogLevel.WARNING, HttpLogOptions.HttpLogDetailLevel.BODY), + Arguments.of(ClientLogger.LogLevel.WARNING, HttpLogOptions.HttpLogDetailLevel.BODY_AND_HEADERS)); + } + + @ParameterizedTest + @MethodSource("allowQueryParamSource") + public void testBasicHttpLogging(Set allowedParams, String expectedUri) throws IOException { + ClientLogger logger = setupLogLevelAndGetLogger(ClientLogger.LogLevel.VERBOSE); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BASIC) + .setAllowedQueryParamNames(allowedParams); + + HttpPipeline pipeline = createPipeline(options); + + HttpRequest request = createRequest(HttpMethod.GET, URI, logger); + Response response = pipeline.send(request); + response.close(); + + List> logMessages = parseLogMessages(); + assertEquals(2, logMessages.size()); + + assertRequestLog(logMessages.get(0), expectedUri, request); + assertEquals(6, logMessages.get(0).size()); + + assertResponseLog(logMessages.get(1), expectedUri, response); + assertEquals(10, logMessages.get(1).size()); + } + + @Test + public void testTryCount() throws IOException { + ClientLogger logger = setupLogLevelAndGetLogger(ClientLogger.LogLevel.VERBOSE); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BASIC); + + HttpPipeline pipeline = createPipeline(options); + + HttpRequest request = createRequest(HttpMethod.GET, URI, logger); + HttpRequestAccessHelper.setRetryCount(request, 42); + Response response = pipeline.send(request); + response.close(); + + List> logMessages = parseLogMessages(); + assertEquals(2, logMessages.size()); + + assertEquals(42, logMessages.get(0).get("tryCount")); + assertEquals(42, logMessages.get(1).get("tryCount")); + } + + @ParameterizedTest + @MethodSource("testExceptionSeverity") + public void testConnectionException(ClientLogger.LogLevel level, boolean expectExceptionLog) { + ClientLogger logger = setupLogLevelAndGetLogger(level); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.HEADERS); + + RuntimeException expectedException = new RuntimeException("socket error"); + HttpPipeline pipeline = createPipeline(options, request -> { + throw expectedException; + }); + + HttpRequest request = createRequest(HttpMethod.GET, URI, logger); + + assertThrows(RuntimeException.class, () -> pipeline.send(request)); + + List> logMessages = parseLogMessages(); + if (!expectExceptionLog) { + assertEquals(0, logMessages.size()); + } else { + assertExceptionLog(logMessages.get(0), REDACTED_URI, request, expectedException); + } + } + + @ParameterizedTest + @MethodSource("testExceptionSeverity") + public void testRequestBodyException(ClientLogger.LogLevel level, boolean expectExceptionLog) { + ClientLogger logger = setupLogLevelAndGetLogger(level); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BODY); + + TestStream requestStream = new TestStream(1024, true, new IOException("socket error")); + BinaryData requestBody = BinaryData.fromStream(requestStream, 1024L); + HttpPipeline pipeline = createPipeline(options); + + HttpRequest request = createRequest(HttpMethod.POST, URI, logger); + request.setBody(requestBody); + + Exception actualException = assertThrows(RuntimeException.class, () -> pipeline.send(request)); + + List> logMessages = parseLogMessages(); + if (!expectExceptionLog) { + assertEquals(0, logMessages.size()); + } else { + assertExceptionLog(logMessages.get(0), REDACTED_URI, request, actualException); + } + } + + @ParameterizedTest + @MethodSource("testExceptionSeverity") + public void testResponseBodyException(ClientLogger.LogLevel level, boolean expectExceptionLog) { + ClientLogger logger = setupLogLevelAndGetLogger(level); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BODY); + + TestStream responseStream = new TestStream(1024, true, new IOException("socket error")); + HttpPipeline pipeline = createPipeline(options, + request -> new MockHttpResponse(request, 200, BinaryData.fromStream(responseStream, 1024L))); + + HttpRequest request = createRequest(HttpMethod.GET, URI, logger); + + Response response = pipeline.send(request); + Exception actualException = assertThrows(RuntimeException.class, () -> response.getBody().toString()); + + List> logMessages = parseLogMessages(); + if (!expectExceptionLog) { + assertEquals(0, logMessages.size()); + } else { + assertResponseAndExceptionLog(logMessages.get(0), REDACTED_URI, response, actualException); + } + } + + @Test + public void testResponseBodyLoggingOnClose() throws IOException { + ClientLogger logger = setupLogLevelAndGetLogger(ClientLogger.LogLevel.INFORMATIONAL); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BODY); + + HttpPipeline pipeline = createPipeline(options, + request -> new MockHttpResponse(request, 200, BinaryData.fromString("Response body"))); + + HttpRequest request = createRequest(HttpMethod.GET, URI, logger); + + Response response = pipeline.send(request); + assertEquals(0, parseLogMessages().size()); + + response.close(); + + List> logMessages = parseLogMessages(); + assertResponseLog(logMessages.get(0), REDACTED_URI, response); + } + + @Test + public void testResponseBodyRequestedMultipleTimes() { + ClientLogger logger = setupLogLevelAndGetLogger(ClientLogger.LogLevel.INFORMATIONAL); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BODY); + + HttpPipeline pipeline = createPipeline(options, + request -> new MockHttpResponse(request, 200, BinaryData.fromString("Response body"))); + + HttpRequest request = createRequest(HttpMethod.GET, URI, logger); + + Response response = pipeline.send(request); + + for (int i = 0; i < 3; i++) { + BinaryData data = response.getBody(); + assertEquals(1, parseLogMessages().size()); + assertEquals("Response body", data.toString()); + } + } + + @ParameterizedTest + @MethodSource("allowQueryParamSource") + public void testBasicHttpLoggingRequestOff(Set allowedParams, String expectedUri) throws IOException { + ClientLogger logger = setupLogLevelAndGetLogger(ClientLogger.LogLevel.INFORMATIONAL); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BASIC) + .setAllowedQueryParamNames(allowedParams); + + HttpPipeline pipeline = createPipeline(options); + + HttpRequest request = createRequest(HttpMethod.POST, URI, logger); + Response response = pipeline.send(request); + response.close(); + + List> logMessages = parseLogMessages(); + assertEquals(1, logMessages.size()); + + assertResponseLog(logMessages.get(0), expectedUri, response); + assertEquals(10, logMessages.get(0).size()); + } + + @ParameterizedTest + @MethodSource("allowedHeaders") + public void testHeadersHttpLogging(Set allowedHeaders) throws IOException { + ClientLogger logger = setupLogLevelAndGetLogger(ClientLogger.LogLevel.VERBOSE); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.HEADERS) + .setAllowedHeaderNames(allowedHeaders); + + HttpPipeline pipeline = createPipeline(options); + + HttpRequest request = createRequest(HttpMethod.GET, URI, logger); + request.getHeaders().set(CUSTOM_REQUEST_ID, "12345"); + Response response = pipeline.send(request); + response.close(); + + List> logMessages = parseLogMessages(); + assertEquals(2, logMessages.size()); + + Map requestLog = logMessages.get(0); + assertRequestLog(requestLog, REDACTED_URI, request); + for (HttpHeader header : request.getHeaders()) { + if (allowedHeaders.contains(header.getName())) { + assertEquals(header.getValue(), requestLog.get(header.getName().toString())); + } else { + assertEquals("REDACTED", requestLog.get(header.getName().toString())); + } + } + + Map responseLog = logMessages.get(1); + assertResponseLog(responseLog, REDACTED_URI, response); + for (HttpHeader header : response.getHeaders()) { + if (allowedHeaders.contains(header.getName())) { + assertEquals(header.getValue(), responseLog.get(header.getName().toString())); + } else { + assertEquals("REDACTED", responseLog.get(header.getName().toString())); + } + } + } + + @Test + public void testStringBodyLogging() throws IOException { + ClientLogger logger = setupLogLevelAndGetLogger(ClientLogger.LogLevel.VERBOSE); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BODY); + + HttpPipeline pipeline = createPipeline(options, + request -> new MockHttpResponse(request, 200, BinaryData.fromString("Response body"))); + + HttpRequest request = createRequest(HttpMethod.PUT, URI, logger); + request.setBody(BinaryData.fromString("Request body")); + + Response response = pipeline.send(request); + response.close(); + + assertEquals("Response body", response.getBody().toString()); + + List> logMessages = parseLogMessages(); + assertEquals(2, logMessages.size()); + + Map requestLog = logMessages.get(0); + assertRequestLog(requestLog, REDACTED_URI, request); + assertEquals("Request body", requestLog.get("body")); + + Map responseLog = logMessages.get(1); + assertResponseLog(responseLog, REDACTED_URI, response); + assertEquals("Response body", responseLog.get("body")); + } + + @Test + public void testHugeBodyNotLogged() throws IOException { + ClientLogger logger = setupLogLevelAndGetLogger(ClientLogger.LogLevel.VERBOSE); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BODY); + + TestStream requestStream = new TestStream(Integer.MAX_VALUE, true); + TestStream responseStream = new TestStream(Integer.MAX_VALUE, true); + HttpPipeline pipeline = createPipeline(options, request -> new MockHttpResponse(request, 200, + BinaryData.fromStream(responseStream, (long) Integer.MAX_VALUE))); + + HttpRequest request = createRequest(HttpMethod.PUT, URI, logger); + + request.setBody(BinaryData.fromStream(requestStream, (long) Integer.MAX_VALUE)); + + Response response = pipeline.send(request); + response.close(); + + List> logMessages = parseLogMessages(); + assertEquals(2, logMessages.size()); + + Map requestLog = logMessages.get(0); + assertRequestLog(requestLog, REDACTED_URI, request); + assertNull(requestLog.get("body")); + assertEquals(0, requestStream.getPosition()); + + Map responseLog = logMessages.get(1); + assertResponseLog(responseLog, REDACTED_URI, response); + assertNull(responseLog.get("body")); + assertEquals(0, responseStream.getPosition()); + } + + @Test + public void testNonReplayableBodyNotLogged() throws IOException { + ClientLogger logger = setupLogLevelAndGetLogger(ClientLogger.LogLevel.VERBOSE); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BODY); + + TestStream requestStream = new TestStream(1024, false); + TestStream responseStream = new TestStream(1024, false); + HttpPipeline pipeline = createPipeline(options, + request -> new MockHttpResponse(request, 200, BinaryData.fromStream(responseStream))); + + HttpRequest request = createRequest(HttpMethod.PUT, URI, logger); + request.getHeaders().set(HttpHeaderName.CONTENT_LENGTH, "1024"); + + request.setBody(BinaryData.fromStream(requestStream)); + + Response response = pipeline.send(request); + response.close(); + + List> logMessages = parseLogMessages(); + assertEquals(2, logMessages.size()); + + Map requestLog = logMessages.get(0); + assertRequestLog(requestLog, REDACTED_URI, request); + assertNull(requestLog.get("body")); + assertEquals(0, requestStream.getPosition()); + + Map responseLog = logMessages.get(1); + assertResponseLog(responseLog, REDACTED_URI, response); + assertNull(responseLog.get("body")); + assertEquals(0, responseStream.getPosition()); + } + + public static Stream allowQueryParamSource() { + Set twoParams = new HashSet<>(); + twoParams.add("param"); + twoParams.add("api-version"); + + return Stream.of(Arguments.of(twoParams, "https://example.com?param=value&api-version=42"), + Arguments.of(DEFAULT_ALLOWED_QUERY_PARAMS, REDACTED_URI), + Arguments.of(Collections.emptySet(), "https://example.com?param=REDACTED&api-version=REDACTED")); + } + + public static Stream> allowedHeaders() { + Set reducedSet = new HashSet<>(); + reducedSet.add(CUSTOM_REQUEST_ID); + + Set expandedSet = new HashSet<>(DEFAULT_ALLOWED_HEADERS); + expandedSet.add(CUSTOM_REQUEST_ID); + + return Stream.of(reducedSet, DEFAULT_ALLOWED_HEADERS, expandedSet); + } + + public static Stream testExceptionSeverity() { + return Stream.of(Arguments.of(ClientLogger.LogLevel.INFORMATIONAL, true), + Arguments.of(ClientLogger.LogLevel.WARNING, true), Arguments.of(ClientLogger.LogLevel.ERROR, false)); + } + + private static class TestStream extends InputStream { + private final long length; + private final boolean replayable; + private final IOException throwOnRead; + private long position = 0; + + TestStream(long length, boolean replayable) { + this.length = length; + this.throwOnRead = null; + this.replayable = replayable; + } + + TestStream(long length, boolean replayable, IOException throwOnRead) { + this.length = length; + this.throwOnRead = throwOnRead; + this.replayable = replayable; + } + + @Override + public int read() throws IOException { + if (throwOnRead != null) { + throw throwOnRead; + } + + if (position >= length) { + return -1; + } + position++; + + return 1; + } + + @Override + public boolean markSupported() { + return replayable; + } + + @Override + public void mark(int readlimit) { + // no-op + } + + @Override + public void reset() throws IOException { + if (!replayable) { + throw new IOException("Stream is not replayable"); + } + + position = 0; + } + + public long getPosition() { + return position; + } + } + + private void assertRequestLog(Map log, String expectedUri, HttpRequest request) { + assertEquals("http.request", log.get("event.name")); + assertEquals(expectedUri, log.get("uri")); + assertEquals(0, (int) log.get("tryCount")); + + assertEquals(getLength(request.getBody(), request.getHeaders()), (int) log.get("requestContentLength")); + assertEquals(request.getHttpMethod().toString(), log.get("method")); + assertEquals("", log.get("message")); + } + + private long getLength(BinaryData body, HttpHeaders headers) { + if (body != null && body.getLength() != null) { + return body.getLength(); + } + + String contentLength = headers.getValue(HttpHeaderName.CONTENT_LENGTH); + if (contentLength != null) { + return Long.parseLong(contentLength); + } + + return 0; + } + + private void assertResponseLog(Map log, String expectedUri, Response response) { + assertEquals("http.response", log.get("event.name")); + assertEquals(expectedUri, log.get("uri")); + assertEquals(0, (int) log.get("tryCount")); + + Long expectedRequestLength = getLength(response.getRequest().getBody(), response.getRequest().getHeaders()); + + assertEquals(expectedRequestLength, (int) log.get("requestContentLength")); + assertEquals(response.getRequest().getHttpMethod().toString(), log.get("method")); + + assertEquals(response.getStatusCode(), log.get("statusCode")); + + Long expectedResponseLength = getLength(response.getBody(), response.getHeaders()); + assertEquals(expectedResponseLength, (int) log.get("responseContentLength")); + assertInstanceOf(Double.class, log.get("timeToHeadersMs")); + assertInstanceOf(Double.class, log.get("durationMs")); + assertEquals("", log.get("message")); + } + + private void assertResponseAndExceptionLog(Map log, String expectedUri, Response response, + Throwable error) { + assertEquals("http.response", log.get("event.name")); + assertEquals(expectedUri, log.get("uri")); + assertEquals(0, (int) log.get("tryCount")); + + Long expectedRequestLength = getLength(response.getRequest().getBody(), response.getRequest().getHeaders()); + + assertEquals(expectedRequestLength, (int) log.get("requestContentLength")); + assertEquals(response.getRequest().getHttpMethod().toString(), log.get("method")); + + assertEquals(response.getStatusCode(), log.get("statusCode")); + + Long expectedResponseLength = getLength(response.getBody(), response.getHeaders()); + assertEquals(expectedResponseLength, (int) log.get("responseContentLength")); + assertInstanceOf(Double.class, log.get("timeToHeadersMs")); + assertInstanceOf(Double.class, log.get("durationMs")); + assertEquals(error.getMessage(), log.get("exception.message")); + assertEquals(error.getClass().getCanonicalName(), log.get("exception.type")); + assertEquals("", log.get("message")); + } + + private void assertExceptionLog(Map log, String expectedUri, HttpRequest request, Throwable error) { + assertEquals("http.response", log.get("event.name")); + assertEquals(expectedUri, log.get("uri")); + assertEquals(0, (int) log.get("tryCount")); + + Long expectedRequestLength = getLength(request.getBody(), request.getHeaders()); + assertEquals(expectedRequestLength, (int) log.get("requestContentLength")); + assertEquals(request.getHttpMethod().toString(), log.get("method")); + + assertNull(log.get("statusCode")); + assertNull(log.get("responseContentLength")); + assertNull(log.get("timeToHeadersMs")); + assertInstanceOf(Double.class, log.get("durationMs")); + assertEquals(error.getMessage(), log.get("exception.message")); + assertEquals(error.getClass().getCanonicalName(), log.get("exception.type")); + + assertEquals("", log.get("message")); + } + + private ClientLogger setupLogLevelAndGetLogger(ClientLogger.LogLevel logLevelToSet) { + DefaultLogger logger + = new DefaultLogger(ClientLogger.class.getName(), new PrintStream(logCaptureStream), logLevelToSet); + + return new ClientLogger(logger, null); + } + + private HttpPipeline createPipeline(HttpLogOptions options) { + return createPipeline(options, request -> { + if (request.getBody() != null) { + request.getBody().toString(); + } + return new MockHttpResponse(request, 200, BinaryData.fromString("Hello, world!")); + }); + } + + private HttpPipeline createPipeline(HttpLogOptions options, Function> httpClient) { + return new HttpPipelineBuilder().policies(new HttpLoggingPolicy(options)).httpClient(httpClient::apply).build(); + } + + private List> parseLogMessages() { + String fullLog = logCaptureStream.toString(StandardCharsets.UTF_8); + return fullLog.lines().map(this::parseLogLine).toList(); + } + + private Map parseLogLine(String logLine) { + String messageJson = logLine.substring(logLine.indexOf(" - ") + 3); + System.out.println(messageJson); + try (JsonReader reader = JsonProviders.createReader(messageJson, new JsonOptions())) { + return reader.readMap(JsonReader::readUntyped); + } catch (IOException e) { + throw new UncheckedIOException(e); + } + } + + private HttpRequest createRequest(HttpMethod method, String url, ClientLogger logger) { + HttpRequest request = new HttpRequest(method, url); + request.getHeaders().set(HttpHeaderName.CONTENT_TYPE, "application/json"); + request.getHeaders().set(HttpHeaderName.AUTHORIZATION, "Bearer {token}"); + request.setRequestOptions(new RequestOptions().setLogger(logger)); + + return request; + } +} From c7845ff9e66a75f0a77203a0881cab9beece1409 Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Thu, 2 Jan 2025 15:49:05 -0800 Subject: [PATCH 2/8] clean up --- .../clientcore/core/http/pipeline/HttpLoggingPolicy.java | 5 +++-- .../clientcore/core/implementation/util/LoggingKeys.java | 7 ++++++- 2 files changed, 9 insertions(+), 3 deletions(-) diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java index f7948dbee76d..6224d87226f0 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java @@ -33,12 +33,13 @@ */ public class HttpLoggingPolicy implements HttpPipelinePolicy { private static final HttpLogOptions DEFAULT_HTTP_LOG_OPTIONS = new HttpLogOptions(); + private static final Set ALWAYS_ALLOWED_HEADERS = Set.of(TRACEPARENT); private static final int MAX_BODY_LOG_SIZE = 1024 * 16; private static final String REDACTED_PLACEHOLDER = "REDACTED"; private static final ClientLogger LOGGER = new ClientLogger(HttpLoggingPolicy.class); private final HttpLogOptions.HttpLogDetailLevel httpLogDetailLevel; private final Set allowedHeaderNames; - private final Set alwaysAllowedHeaders = Set.of(TRACEPARENT); + private final Set allowedQueryParameterNames; private static final String HTTP_REQUEST_EVENT_NAME = "http.request"; @@ -298,7 +299,7 @@ private void addHeadersToLogMessage(HttpHeaders headers, ClientLogger.LoggingEve logBuilder.addKeyValue(headerName.toString(), headerValue); } } else { - for (HttpHeaderName headerName : alwaysAllowedHeaders) { + for (HttpHeaderName headerName : ALWAYS_ALLOWED_HEADERS) { String headerValue = headers.getValue(headerName); if (headerValue != null) { logBuilder.addKeyValue(headerName.toString(), headerValue); diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/util/LoggingKeys.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/util/LoggingKeys.java index 1a6136c4cdd6..be4548633089 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/util/LoggingKeys.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/util/LoggingKeys.java @@ -36,7 +36,12 @@ private LoggingKeys() { /** * Key representing duration of call in milliseconds, the value should be a number. *

- * This time can + * This time represents the most accurate duration that logging policy can record. + *

+ * If exception was thrown, this time represents time to exception. + * If response was received and body logging is disabled, it represents time to get the response (headers and status code). + * If response was received and body logging is enabled, it represents time-to-last-byte (or, if response was closed before + * body was fully received, time to closure). */ public static final String DURATION_MS_KEY = "durationMs"; From ab64876c7c18b5010455727e26befcdffe8b9d38 Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Thu, 2 Jan 2025 16:40:47 -0800 Subject: [PATCH 3/8] fix replayable --- .../core/http/pipeline/HttpLoggingPolicy.java | 41 ++++--- .../core/util/HttpLoggingPolicyTests.java | 105 +++++++++++------- 2 files changed, 85 insertions(+), 61 deletions(-) diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java index 6224d87226f0..d90fd1e8fa07 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java @@ -11,7 +11,6 @@ import io.clientcore.core.http.models.HttpResponse; import io.clientcore.core.http.models.Response; import io.clientcore.core.implementation.http.HttpRequestAccessHelper; -import io.clientcore.core.implementation.http.HttpResponseAccessHelper; import io.clientcore.core.implementation.util.ImplUtils; import io.clientcore.core.implementation.util.LoggingKeys; import io.clientcore.core.util.ClientLogger; @@ -129,7 +128,9 @@ private void logRequest(ClientLogger logger, HttpRequest request, long startNano if (httpLogDetailLevel.shouldLogBody() && canLogBody(request.getBody())) { String content; try { - content = request.getBody().toString(); + BinaryData bufferedBody = request.getBody().toReplayableBinaryData(); + request.setBody(bufferedBody); + content = bufferedBody.toString(); } catch (RuntimeException e) { // we'll log exception at the appropriate level. throw logException(logger, request, null, e, startNanoTime, null, requestContentLength, redactedUrl, @@ -169,7 +170,7 @@ private Response logResponse(ClientLogger logger, Response response, long if (httpLogDetailLevel.shouldLogBody() && canLogBody(response.getBody())) { return new LoggingHttpResponse<>(response, content -> { if (logBuilder.isEnabled()) { - logBuilder.addKeyValue(LoggingKeys.BODY_KEY, content) + logBuilder.addKeyValue(LoggingKeys.BODY_KEY, content.toString()) .addKeyValue(LoggingKeys.DURATION_MS_KEY, getDurationMs(startNanoTime, System.nanoTime())) .log(); } @@ -231,11 +232,7 @@ private double getDurationMs(long startNs, long endNs) { private static boolean canLogBody(BinaryData data) { // TODO: limolkova - we might want to filter out binary data, but // if somebody enabled logging it - why not log it? - return data != null - && data.isReplayable() - && data.getLength() != null - && data.getLength() > 0 - && data.getLength() < MAX_BODY_LOG_SIZE; + return data != null && data.getLength() != null && data.getLength() > 0 && data.getLength() < MAX_BODY_LOG_SIZE; } /** @@ -344,32 +341,31 @@ private static long getContentLength(ClientLogger logger, BinaryData body, HttpH } private static final class LoggingHttpResponse extends HttpResponse { - private boolean logged = false; - private final Consumer onContent; + private final Consumer onContent; private final Consumer onException; + private final BinaryData originalBody; + private BinaryData bufferedBody; - private LoggingHttpResponse(Response actualResponse, Consumer onContent, + private LoggingHttpResponse(Response actualResponse, Consumer onContent, Consumer onException) { super(actualResponse.getRequest(), actualResponse.getStatusCode(), actualResponse.getHeaders(), actualResponse.getValue()); - HttpResponseAccessHelper.setBody(this, actualResponse.getBody()); - this.onContent = onContent; this.onException = onException; + this.originalBody = actualResponse.getBody(); } @Override public BinaryData getBody() { - if (logged) { - return super.getBody(); + if (bufferedBody != null) { + return bufferedBody; } - logged = true; try { - BinaryData content = super.getBody(); - onContent.accept(content.toString()); - return content; + bufferedBody = originalBody.toReplayableBinaryData(); + onContent.accept(bufferedBody); + return bufferedBody; } catch (RuntimeException e) { // we'll log exception at the appropriate level. onException.accept(e); @@ -379,10 +375,13 @@ public BinaryData getBody() { @Override public void close() throws IOException { - if (!logged) { + if (bufferedBody == null) { getBody(); } - super.close(); + if (bufferedBody != null) { + bufferedBody.close(); + } + originalBody.close(); } } } diff --git a/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java b/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java index bdc429666679..b181abe14dfb 100644 --- a/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java +++ b/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java @@ -44,9 +44,11 @@ import java.util.stream.Stream; import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertFalse; import static org.junit.jupiter.api.Assertions.assertInstanceOf; import static org.junit.jupiter.api.Assertions.assertNull; import static org.junit.jupiter.api.Assertions.assertThrows; +import static org.junit.jupiter.api.Assertions.assertTrue; @Execution(ExecutionMode.SAME_THREAD) public class HttpLoggingPolicyTests { @@ -156,7 +158,7 @@ public void testRequestBodyException(ClientLogger.LogLevel level, boolean expect ClientLogger logger = setupLogLevelAndGetLogger(level); HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BODY); - TestStream requestStream = new TestStream(1024, true, new IOException("socket error")); + TestStream requestStream = new TestStream(1024, new IOException("socket error")); BinaryData requestBody = BinaryData.fromStream(requestStream, 1024L); HttpPipeline pipeline = createPipeline(options); @@ -179,7 +181,7 @@ public void testResponseBodyException(ClientLogger.LogLevel level, boolean expec ClientLogger logger = setupLogLevelAndGetLogger(level); HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BODY); - TestStream responseStream = new TestStream(1024, true, new IOException("socket error")); + TestStream responseStream = new TestStream(1024, new IOException("socket error")); HttpPipeline pipeline = createPipeline(options, request -> new MockHttpResponse(request, 200, BinaryData.fromStream(responseStream, 1024L))); @@ -321,18 +323,56 @@ public void testStringBodyLogging() throws IOException { } @Test - public void testHugeBodyNotLogged() throws IOException { + public void testStreamBodyLogging() { ClientLogger logger = setupLogLevelAndGetLogger(ClientLogger.LogLevel.VERBOSE); HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BODY); - TestStream requestStream = new TestStream(Integer.MAX_VALUE, true); - TestStream responseStream = new TestStream(Integer.MAX_VALUE, true); + BinaryData responseBody = BinaryData.fromString("Response body"); + TestStream responseStream = new TestStream(responseBody); + HttpPipeline pipeline = createPipeline(options, request -> new MockHttpResponse(request, 200, - BinaryData.fromStream(responseStream, (long) Integer.MAX_VALUE))); + BinaryData.fromStream(responseStream, responseBody.getLength()))); + + BinaryData requestBody = BinaryData.fromString("Request body"); + TestStream requestStream = new TestStream(requestBody); + HttpRequest request = createRequest(HttpMethod.PUT, URI, logger); + request.setBody(BinaryData.fromStream(requestStream, requestBody.getLength())); + assertFalse(request.getBody().isReplayable()); + + Response response = pipeline.send(request); + assertTrue(request.getBody().isReplayable()); + assertTrue(response.getBody().isReplayable()); + + assertEquals("Response body", response.getBody().toString()); + + List> logMessages = parseLogMessages(); + assertEquals(2, logMessages.size()); + + Map requestLog = logMessages.get(0); + assertRequestLog(requestLog, REDACTED_URI, request); + assertEquals("Request body", requestLog.get("body")); + + Map responseLog = logMessages.get(1); + assertResponseLog(responseLog, REDACTED_URI, response); + assertEquals("Response body", responseLog.get("body")); + + assertEquals(requestBody.getLength(), requestStream.getPosition()); + assertEquals(responseBody.getLength(), responseStream.getPosition()); + } + + @Test + public void testHugeBodyNotLogged() throws IOException { + ClientLogger logger = setupLogLevelAndGetLogger(ClientLogger.LogLevel.VERBOSE); + HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BODY); + + TestStream requestStream = new TestStream(1024 * 1024); + TestStream responseStream = new TestStream(1024 * 1024); + HttpPipeline pipeline = createPipeline(options, + request -> new MockHttpResponse(request, 200, BinaryData.fromStream(responseStream, (long) 1024 * 1024))); HttpRequest request = createRequest(HttpMethod.PUT, URI, logger); - request.setBody(BinaryData.fromStream(requestStream, (long) Integer.MAX_VALUE)); + request.setBody(BinaryData.fromStream(requestStream, 1024 * 1024L)); Response response = pipeline.send(request); response.close(); @@ -352,12 +392,12 @@ public void testHugeBodyNotLogged() throws IOException { } @Test - public void testNonReplayableBodyNotLogged() throws IOException { + public void testBodyWithUnknownLengthNotLogged() throws IOException { ClientLogger logger = setupLogLevelAndGetLogger(ClientLogger.LogLevel.VERBOSE); HttpLogOptions options = new HttpLogOptions().setLogLevel(HttpLogOptions.HttpLogDetailLevel.BODY); - TestStream requestStream = new TestStream(1024, false); - TestStream responseStream = new TestStream(1024, false); + TestStream requestStream = new TestStream(1024); + TestStream responseStream = new TestStream(1024); HttpPipeline pipeline = createPipeline(options, request -> new MockHttpResponse(request, 200, BinaryData.fromStream(responseStream))); @@ -409,21 +449,27 @@ public static Stream testExceptionSeverity() { } private static class TestStream extends InputStream { - private final long length; - private final boolean replayable; + private final byte[] content; + private int length; private final IOException throwOnRead; - private long position = 0; + private int position = 0; - TestStream(long length, boolean replayable) { + TestStream(int length) { this.length = length; this.throwOnRead = null; - this.replayable = replayable; + this.content = new byte[length]; + } + + TestStream(BinaryData content) { + this.length = content.getLength().intValue(); + this.throwOnRead = null; + this.content = content.toBytes(); } - TestStream(long length, boolean replayable, IOException throwOnRead) { + TestStream(int length, IOException throwOnRead) { this.length = length; this.throwOnRead = throwOnRead; - this.replayable = replayable; + this.content = new byte[length]; } @Override @@ -435,28 +481,9 @@ public int read() throws IOException { if (position >= length) { return -1; } - position++; - return 1; - } - - @Override - public boolean markSupported() { - return replayable; - } - - @Override - public void mark(int readlimit) { - // no-op - } - - @Override - public void reset() throws IOException { - if (!replayable) { - throw new IOException("Stream is not replayable"); - } - - position = 0; + position++; + return content[position - 1]; } public long getPosition() { @@ -519,8 +546,6 @@ private void assertResponseAndExceptionLog(Map log, String expec assertEquals(response.getStatusCode(), log.get("statusCode")); - Long expectedResponseLength = getLength(response.getBody(), response.getHeaders()); - assertEquals(expectedResponseLength, (int) log.get("responseContentLength")); assertInstanceOf(Double.class, log.get("timeToHeadersMs")); assertInstanceOf(Double.class, log.get("durationMs")); assertEquals(error.getMessage(), log.get("exception.message")); From 9588c6d39793bc2d4ef6901ca0406f455958c843 Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Thu, 2 Jan 2025 16:43:14 -0800 Subject: [PATCH 4/8] up --- .../io/clientcore/core/http/pipeline/HttpLoggingPolicy.java | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java index d90fd1e8fa07..48074c677dff 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java @@ -126,18 +126,15 @@ private void logRequest(ClientLogger logger, HttpRequest request, long startNano addHeadersToLogMessage(request.getHeaders(), logBuilder); if (httpLogDetailLevel.shouldLogBody() && canLogBody(request.getBody())) { - String content; try { BinaryData bufferedBody = request.getBody().toReplayableBinaryData(); request.setBody(bufferedBody); - content = bufferedBody.toString(); + logBuilder.addKeyValue(LoggingKeys.BODY_KEY, bufferedBody.toString()); } catch (RuntimeException e) { // we'll log exception at the appropriate level. throw logException(logger, request, null, e, startNanoTime, null, requestContentLength, redactedUrl, tryCount); } - - logBuilder.addKeyValue(LoggingKeys.BODY_KEY, content); } logBuilder.log(); From 528611f413d24cfd82e5d47a88cbfff25f34c2ab Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Fri, 3 Jan 2025 10:07:40 -0800 Subject: [PATCH 5/8] retry count -> try count --- .../core/http/models/HttpRequest.java | 28 +++++++------ .../core/http/pipeline/HttpLoggingPolicy.java | 2 +- .../pipeline/HttpRequestRetryCondition.java | 2 +- .../core/http/pipeline/HttpRetryPolicy.java | 5 ++- .../http/HttpRequestAccessHelper.java | 40 ++++++++++--------- .../core/util/HttpLoggingPolicyTests.java | 2 +- 6 files changed, 44 insertions(+), 35 deletions(-) diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/HttpRequest.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/HttpRequest.java index 292b5ac5e278..68c471617fab 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/HttpRequest.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/models/HttpRequest.java @@ -26,13 +26,13 @@ public class HttpRequest { static { HttpRequestAccessHelper.setAccessor(new HttpRequestAccessHelper.HttpRequestAccessor() { @Override - public int getRetryCount(HttpRequest httpRequest) { - return httpRequest.getRetryCount(); + public int getTryCount(HttpRequest httpRequest) { + return httpRequest.getTryCount(); } @Override - public HttpRequest setRetryCount(HttpRequest httpRequest, int retryCount) { - return httpRequest.setRetryCount(retryCount); + public HttpRequest setTryCount(HttpRequest httpRequest, int tryCount) { + return httpRequest.setTryCount(tryCount); } }); } @@ -43,7 +43,7 @@ public HttpRequest setRetryCount(HttpRequest httpRequest, int retryCount) { private BinaryData body; private ServerSentEventListener serverSentEventListener; private RequestOptions requestOptions; - private int retryCount; + private int tryCount; /** * Create a new {@link HttpRequest} instance. @@ -233,22 +233,24 @@ public HttpRequest setServerSentEventListener(ServerSentEventListener serverSent } /** - * Gets the number of times the request has been retried. + * Gets the number of times the request has been attempted. It's 0 during the first attempt + * and increments after attempt is made. * - * @return The number of times the request has been retried. + * @return The number of times the request has been attempted. */ - private int getRetryCount() { - return retryCount; + private int getTryCount() { + return tryCount; } /** - * Sets the number of times the request has been retried. + * Sets the number of times the request has been attempted. It's 0 during the first attempt + * and increments after attempt is made. * - * @param retryCount The number of times the request has been retried. + * @param tryCount The number of times the request has been attempted. * @return The updated {@link HttpRequest} object. */ - private HttpRequest setRetryCount(int retryCount) { - this.retryCount = retryCount; + private HttpRequest setTryCount(int tryCount) { + this.tryCount = tryCount; return this; } diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java index 48074c677dff..29804b027519 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java @@ -75,7 +75,7 @@ public Response process(HttpRequest httpRequest, HttpPipelineNextPolicy next) final long startNs = System.nanoTime(); final String redactedUrl = getRedactedUri(httpRequest.getUri(), allowedQueryParameterNames); - final int tryCount = HttpRequestAccessHelper.getRetryCount(httpRequest); + final int tryCount = HttpRequestAccessHelper.getTryCount(httpRequest); final long requestContentLength = httpRequest.getBody() == null ? 0 : getContentLength(logger, httpRequest.getBody(), httpRequest.getHeaders()); diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRequestRetryCondition.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRequestRetryCondition.java index ac2d7128f268..ac664f8c5037 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRequestRetryCondition.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRequestRetryCondition.java @@ -22,7 +22,7 @@ public final class HttpRequestRetryCondition { * * @param response The HTTP response of the request that failed. * @param exception The exception of the request that failed. - * @param tryCount The number of tries that have been attempted. + * @param tryCount The number of tries that have been already attempted. * @param retriedExceptions The list of exceptions that have been encountered during retries. */ HttpRequestRetryCondition(Response response, Exception exception, int tryCount, diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRetryPolicy.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRetryPolicy.java index 0146627161d1..e4a4a5a2d888 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRetryPolicy.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRetryPolicy.java @@ -136,7 +136,10 @@ private Duration getWellKnownRetryDelay(HttpHeaders responseHeaders, int tryCoun private Response attempt(final HttpRequest httpRequest, final HttpPipelineNextPolicy next, final int tryCount, final List suppressed) { - HttpRequestAccessHelper.setRetryCount(httpRequest, tryCount); + + // the tryCount is updated by the caller and represents the number of attempts made so far. + // It can be used by the policies during the process call. + HttpRequestAccessHelper.setTryCount(httpRequest, tryCount); Response response; diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/http/HttpRequestAccessHelper.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/http/HttpRequestAccessHelper.java index ebcfe16327b2..3a2e75cfca7e 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/http/HttpRequestAccessHelper.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/http/HttpRequestAccessHelper.java @@ -16,46 +16,50 @@ public final class HttpRequestAccessHelper { */ public interface HttpRequestAccessor { /** - * Gets the number of times the request has been retried. + * Gets the number of times the request has been attempted. It's 0 during the first attempt + * and increments after attempt is made. * - * @param httpRequest The {@link HttpRequest} to set the retry count of. + * @param httpRequest The {@link HttpRequest} to set the try count of. * - * @return The {@link HttpRequest} retry count. + * @return The {@link HttpRequest} try count. */ - int getRetryCount(HttpRequest httpRequest); + int getTryCount(HttpRequest httpRequest); /** - * Sets the number of times the request has been retried. + * Sets the number of times the request has been attempted. It's 0 during the first attempt + * and increments after attempt is made. * - * @param httpRequest The {@link HttpRequest} to set the retry count of. - * @param retryCount The number of times the request has been retried. + * @param httpRequest The {@link HttpRequest} to set the try count of. + * @param tryCount The number of times the request has been attempted. * * @return The modified {@link HttpRequest}. */ - HttpRequest setRetryCount(HttpRequest httpRequest, int retryCount); + HttpRequest setTryCount(HttpRequest httpRequest, int tryCount); } /** - * Gets the number of times the request has been retried. + * Gets the number of times the request has already been retried. It's 0 during the first attempt + * and increments after attempt is made. * - * @param httpRequest The {@link HttpRequest} to set the retry count of. + * @param httpRequest The {@link HttpRequest} to set the try count of. * - * @return The {@link HttpRequest} retry count. + * @return The {@link HttpRequest} try count. */ - public static int getRetryCount(HttpRequest httpRequest) { - return accessor.getRetryCount(httpRequest); + public static int getTryCount(HttpRequest httpRequest) { + return accessor.getTryCount(httpRequest); } /** - * Sets the number of times the request has been retried. + * Sets the number of times the request has been attempted. It's 0 during the first attempt + * and increments after attempt is made. * - * @param httpRequest The {@link HttpRequest} to set the retry count of. - * @param retryCount The number of times the request has been retried. + * @param httpRequest The {@link HttpRequest} to set the try count of. + * @param tryCount The number of times the request has been retried. * * @return The updated {@link HttpRequest} object. */ - public static HttpRequest setRetryCount(HttpRequest httpRequest, int retryCount) { - return accessor.setRetryCount(httpRequest, retryCount); + public static HttpRequest setTryCount(HttpRequest httpRequest, int tryCount) { + return accessor.setTryCount(httpRequest, tryCount); } /** diff --git a/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java b/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java index b181abe14dfb..c04016837730 100644 --- a/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java +++ b/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java @@ -118,7 +118,7 @@ public void testTryCount() throws IOException { HttpPipeline pipeline = createPipeline(options); HttpRequest request = createRequest(HttpMethod.GET, URI, logger); - HttpRequestAccessHelper.setRetryCount(request, 42); + HttpRequestAccessHelper.setTryCount(request, 42); Response response = pipeline.send(request); response.close(); From 90aee3c897d28962090c7d0fd376bb9ecb3bb7af Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Fri, 3 Jan 2025 14:00:06 -0800 Subject: [PATCH 6/8] feedback: part 2 --- .../core/http/pipeline/HttpLoggingPolicy.java | 14 +++++++------- .../core/implementation/util/LoggingKeys.java | 4 ++-- .../java/io/clientcore/core/util/ClientLogger.java | 4 +--- 3 files changed, 10 insertions(+), 12 deletions(-) diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java index 29804b027519..30c7bd6cb505 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java @@ -147,7 +147,7 @@ private Response logResponse(ClientLogger logger, Response response, long return response; } - long timeToHeadersNanoTime = System.nanoTime(); + long responseStartNanoTime = System.nanoTime(); // response may be disabled, but we still need to log the exception if an exception occurs during stream reading. if (logBuilder.isEnabled()) { @@ -155,7 +155,7 @@ private Response logResponse(ClientLogger logger, Response response, long .addKeyValue(LoggingKeys.HTTP_METHOD_KEY, response.getRequest().getHttpMethod()) .addKeyValue(LoggingKeys.TRY_COUNT_KEY, tryCount) .addKeyValue(LoggingKeys.URI_KEY, redactedUrl) - .addKeyValue(LoggingKeys.TIME_TO_HEADERS_MS, getDurationMs(startNanoTime, timeToHeadersNanoTime)) + .addKeyValue(LoggingKeys.TIME_TO_RESPONSE_MS_KEY, getDurationMs(startNanoTime, responseStartNanoTime)) .addKeyValue(LoggingKeys.STATUS_CODE_KEY, response.getStatusCode()) .addKeyValue(LoggingKeys.REQUEST_CONTENT_LENGTH_KEY, requestContentLength) .addKeyValue(LoggingKeys.RESPONSE_CONTENT_LENGTH_KEY, @@ -172,7 +172,7 @@ private Response logResponse(ClientLogger logger, Response response, long .log(); } }, throwable -> logException(logger, response.getRequest(), response, throwable, startNanoTime, - timeToHeadersNanoTime, requestContentLength, redactedUrl, tryCount)); + responseStartNanoTime, requestContentLength, redactedUrl, tryCount)); } if (logBuilder.isEnabled()) { @@ -183,7 +183,7 @@ private Response logResponse(ClientLogger logger, Response response, long } private T logException(ClientLogger logger, HttpRequest request, Response response, - T throwable, long startNanoTime, Long timeToHeadersNanoTime, long requestContentLength, String redactedUrl, + T throwable, long startNanoTime, Long responseStartNanoTime, long requestContentLength, String redactedUrl, int tryCount) { ClientLogger.LoggingEventBuilder logBuilder = logger.atLevel(ClientLogger.LogLevel.WARNING); if (!logBuilder.isEnabled() || httpLogDetailLevel == HttpLogOptions.HttpLogDetailLevel.NONE) { @@ -204,9 +204,9 @@ private T logException(ClientLogger logger, HttpRequest re getContentLength(logger, response.getBody(), response.getHeaders())) .addKeyValue(LoggingKeys.STATUS_CODE_KEY, response.getStatusCode()); - if (timeToHeadersNanoTime != null) { - logBuilder.addKeyValue(LoggingKeys.TIME_TO_HEADERS_MS, - getDurationMs(startNanoTime, timeToHeadersNanoTime)); + if (responseStartNanoTime != null) { + logBuilder.addKeyValue(LoggingKeys.TIME_TO_RESPONSE_MS_KEY, + getDurationMs(startNanoTime, responseStartNanoTime)); } } diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/util/LoggingKeys.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/util/LoggingKeys.java index be4548633089..568799979296 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/util/LoggingKeys.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/implementation/util/LoggingKeys.java @@ -26,12 +26,12 @@ private LoggingKeys() { public static final String TRY_COUNT_KEY = "tryCount"; /** - * Key representing time from request start to the moment response (headers and response code) were received in milliseconds, + * Key representing time in milliseconds from request start to the moment response (headers and response code) were received, * the value should be a number. *

* Depending on the implementation and content type, this time may include time to receive the body. */ - public static final String TIME_TO_HEADERS_MS = "timeToHeadersMs"; + public static final String TIME_TO_RESPONSE_MS_KEY = "timeToResponseMs"; /** * Key representing duration of call in milliseconds, the value should be a number. diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/util/ClientLogger.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/util/ClientLogger.java index 442b5053dad4..c85851b3b317 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/util/ClientLogger.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/util/ClientLogger.java @@ -446,9 +446,7 @@ public LoggingEventBuilder setEventName(String eventName) { * Logs event annotated with context. */ public void log() { - if (this.isEnabled) { - logger.performLogging(level, getMessageWithContext(null), null); - } + log(null); } /** From 63b5158ed900cb4abb004272f962c437d7b550e6 Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Fri, 3 Jan 2025 14:04:16 -0800 Subject: [PATCH 7/8] logging event builder -> logging event --- .../core/http/pipeline/HttpLoggingPolicy.java | 8 +- .../core/http/pipeline/HttpRetryPolicy.java | 6 +- .../io/clientcore/core/util/ClientLogger.java | 80 +++++++++---------- .../native-image.properties | 2 +- .../core/util/HttpLoggingPolicyTests.java | 6 +- 5 files changed, 51 insertions(+), 51 deletions(-) diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java index 30c7bd6cb505..55cc757d4a2e 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java @@ -112,7 +112,7 @@ private ClientLogger getLogger(HttpRequest request) { private void logRequest(ClientLogger logger, HttpRequest request, long startNanoTime, long requestContentLength, String redactedUrl, int tryCount) { - ClientLogger.LoggingEventBuilder logBuilder = logger.atLevel(HTTP_REQUEST_LOG_LEVEL); + ClientLogger.LoggingEvent logBuilder = logger.atLevel(HTTP_REQUEST_LOG_LEVEL); if (!logBuilder.isEnabled() || httpLogDetailLevel == HttpLogOptions.HttpLogDetailLevel.NONE) { return; } @@ -142,7 +142,7 @@ private void logRequest(ClientLogger logger, HttpRequest request, long startNano private Response logResponse(ClientLogger logger, Response response, long startNanoTime, long requestContentLength, String redactedUrl, int tryCount) { - ClientLogger.LoggingEventBuilder logBuilder = logger.atLevel(HTTP_RESPONSE_LOG_LEVEL); + ClientLogger.LoggingEvent logBuilder = logger.atLevel(HTTP_RESPONSE_LOG_LEVEL); if (httpLogDetailLevel == HttpLogOptions.HttpLogDetailLevel.NONE) { return response; } @@ -185,7 +185,7 @@ private Response logResponse(ClientLogger logger, Response response, long private T logException(ClientLogger logger, HttpRequest request, Response response, T throwable, long startNanoTime, Long responseStartNanoTime, long requestContentLength, String redactedUrl, int tryCount) { - ClientLogger.LoggingEventBuilder logBuilder = logger.atLevel(ClientLogger.LogLevel.WARNING); + ClientLogger.LoggingEvent logBuilder = logger.atLevel(ClientLogger.LogLevel.WARNING); if (!logBuilder.isEnabled() || httpLogDetailLevel == HttpLogOptions.HttpLogDetailLevel.NONE) { return throwable; } @@ -285,7 +285,7 @@ private static String getRedactedUri(URI uri, Set allowedQueryParameterN * @param headers HTTP headers on the request or response. * @param logBuilder Log message builder. */ - private void addHeadersToLogMessage(HttpHeaders headers, ClientLogger.LoggingEventBuilder logBuilder) { + private void addHeadersToLogMessage(HttpHeaders headers, ClientLogger.LoggingEvent logBuilder) { if (httpLogDetailLevel.shouldLogHeaders()) { for (HttpHeader header : headers) { HttpHeaderName headerName = header.getName(); diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRetryPolicy.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRetryPolicy.java index e4a4a5a2d888..477e2119a0eb 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRetryPolicy.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpRetryPolicy.java @@ -280,9 +280,9 @@ private static void logRetryExhausted(int tryCount) { LOGGER.atInfo().addKeyValue(LoggingKeys.TRY_COUNT_KEY, tryCount).log("Retry attempts have been exhausted."); } - private static void logRetryWithError(ClientLogger.LoggingEventBuilder loggingEventBuilder, int tryCount, - String message, Throwable throwable) { - loggingEventBuilder.addKeyValue(LoggingKeys.TRY_COUNT_KEY, tryCount).log(message, throwable); + private static void logRetryWithError(ClientLogger.LoggingEvent loggingEvent, int tryCount, String message, + Throwable throwable) { + loggingEvent.addKeyValue(LoggingKeys.TRY_COUNT_KEY, tryCount).log(message, throwable); } private Duration calculateRetryDelay(int retryAttempts) { diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/util/ClientLogger.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/util/ClientLogger.java index c85851b3b317..6fea3c48010d 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/util/ClientLogger.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/util/ClientLogger.java @@ -108,7 +108,7 @@ public ClientLogger(Class clazz, Map context) { */ public T logThrowableAsWarning(T throwable) { Objects.requireNonNull(throwable, "'throwable' cannot be null."); - LoggingEventBuilder.create(logger, LogLevel.WARNING, globalContext).log(throwable.getMessage(), throwable); + LoggingEvent.create(logger, LogLevel.WARNING, globalContext).log(throwable.getMessage(), throwable); return throwable; } @@ -125,7 +125,7 @@ public T logThrowableAsWarning(T throwable) { */ public T logThrowableAsError(T throwable) { Objects.requireNonNull(throwable, "'throwable' cannot be null."); - LoggingEventBuilder.create(logger, LogLevel.ERROR, globalContext).log(throwable.getMessage(), throwable); + LoggingEvent.create(logger, LogLevel.ERROR, globalContext).log(throwable.getMessage(), throwable); return throwable; } @@ -140,7 +140,7 @@ public boolean canLogAtLevel(LogLevel logLevel) { } /** - * Creates {@link LoggingEventBuilder} for {@code error} log level that can be + * Creates {@link LoggingEvent} for {@code error} log level that can be * used to enrich log with additional context. *

Code samples

* @@ -154,14 +154,14 @@ public boolean canLogAtLevel(LogLevel logLevel) { * * * - * @return instance of {@link LoggingEventBuilder} or no-op if error logging is disabled. + * @return instance of {@link LoggingEvent} or no-op if error logging is disabled. */ - public LoggingEventBuilder atError() { - return LoggingEventBuilder.create(logger, LogLevel.ERROR, globalContext); + public LoggingEvent atError() { + return LoggingEvent.create(logger, LogLevel.ERROR, globalContext); } /** - * Creates {@link LoggingEventBuilder} for {@code warning} log level that can be + * Creates {@link LoggingEvent} for {@code warning} log level that can be * used to enrich log with additional context. *

Code samples

* @@ -175,14 +175,14 @@ public LoggingEventBuilder atError() { * * * - * @return instance of {@link LoggingEventBuilder} or no-op if warn logging is disabled. + * @return instance of {@link LoggingEvent} or no-op if warn logging is disabled. */ - public LoggingEventBuilder atWarning() { - return LoggingEventBuilder.create(logger, LogLevel.WARNING, globalContext); + public LoggingEvent atWarning() { + return LoggingEvent.create(logger, LogLevel.WARNING, globalContext); } /** - * Creates {@link LoggingEventBuilder} for {@code info} log level that can be + * Creates {@link LoggingEvent} for {@code info} log level that can be * used to enrich log with additional context. * *

Code samples

@@ -198,14 +198,14 @@ public LoggingEventBuilder atWarning() { * * * - * @return instance of {@link LoggingEventBuilder} or no-op if info logging is disabled. + * @return instance of {@link LoggingEvent} or no-op if info logging is disabled. */ - public LoggingEventBuilder atInfo() { - return LoggingEventBuilder.create(logger, LogLevel.INFORMATIONAL, globalContext); + public LoggingEvent atInfo() { + return LoggingEvent.create(logger, LogLevel.INFORMATIONAL, globalContext); } /** - * Creates {@link LoggingEventBuilder} for {@code verbose} log level that can be + * Creates {@link LoggingEvent} for {@code verbose} log level that can be * used to enrich log with additional context. *

Code samples

* @@ -219,14 +219,14 @@ public LoggingEventBuilder atInfo() { * * * - * @return instance of {@link LoggingEventBuilder} or no-op if verbose logging is disabled. + * @return instance of {@link LoggingEvent} or no-op if verbose logging is disabled. */ - public LoggingEventBuilder atVerbose() { - return LoggingEventBuilder.create(logger, LogLevel.VERBOSE, globalContext); + public LoggingEvent atVerbose() { + return LoggingEvent.create(logger, LogLevel.VERBOSE, globalContext); } /** - * Creates {@link LoggingEventBuilder} for log level that can be + * Creates {@link LoggingEvent} for log level that can be * used to enrich log with additional context. * *

Code samples

@@ -244,10 +244,10 @@ public LoggingEventBuilder atVerbose() { * * * @param level log level. - * @return instance of {@link LoggingEventBuilder} or no-op if logging at provided level is disabled. + * @return instance of {@link LoggingEvent} or no-op if logging at provided level is disabled. */ - public LoggingEventBuilder atLevel(LogLevel level) { - return LoggingEventBuilder.create(logger, level, globalContext); + public LoggingEvent atLevel(LogLevel level) { + return LoggingEvent.create(logger, level, globalContext); } private static String getClassPathFromClassName(String className) { @@ -279,8 +279,8 @@ private static String getClassPathFromClassName(String className) { * */ @Metadata(conditions = FLUENT) - public static final class LoggingEventBuilder { - private static final LoggingEventBuilder NOOP = new LoggingEventBuilder(null, null, null, false); + public static final class LoggingEvent { + private static final LoggingEvent NOOP = new LoggingEvent(null, null, null, false); private final Slf4jLoggerShim logger; private final LogLevel level; @@ -290,18 +290,18 @@ public static final class LoggingEventBuilder { private String eventName; /** - * Creates {@code LoggingEventBuilder} for provided level and {@link ClientLogger}. + * Creates {@code LoggingEvent} for provided level and {@link ClientLogger}. * If level is disabled, returns no-op instance. */ - static LoggingEventBuilder create(Slf4jLoggerShim logger, LogLevel level, Map globalContext) { + static LoggingEvent create(Slf4jLoggerShim logger, LogLevel level, Map globalContext) { if (logger.canLogAtLevel(level)) { - return new LoggingEventBuilder(logger, level, globalContext, true); + return new LoggingEvent(logger, level, globalContext, true); } return NOOP; } - private LoggingEventBuilder(Slf4jLoggerShim logger, LogLevel level, Map globalContext, + private LoggingEvent(Slf4jLoggerShim logger, LogLevel level, Map globalContext, boolean isEnabled) { this.logger = logger; this.level = level; @@ -336,9 +336,9 @@ public boolean isEnabled() { * * @param key String key. * @param value String value. - * @return The updated {@code LoggingEventBuilder} object. + * @return The updated {@code LoggingEvent} object. */ - public LoggingEventBuilder addKeyValue(String key, String value) { + public LoggingEvent addKeyValue(String key, String value) { if (this.isEnabled) { addKeyValueInternal(key, value); } @@ -366,9 +366,9 @@ public LoggingEventBuilder addKeyValue(String key, String value) { * * @param key String key. * @param value Object value. - * @return The updated {@code LoggingEventBuilder} object. + * @return The updated {@code LoggingEvent} object. */ - public LoggingEventBuilder addKeyValue(String key, Object value) { + public LoggingEvent addKeyValue(String key, Object value) { if (this.isEnabled) { addKeyValueInternal(key, value); } @@ -381,9 +381,9 @@ public LoggingEventBuilder addKeyValue(String key, Object value) { * * @param key Key to associate the provided {@code value} with. * @param value The boolean value. - * @return The updated {@link LoggingEventBuilder} object. + * @return The updated {@link LoggingEvent} object. */ - public LoggingEventBuilder addKeyValue(String key, boolean value) { + public LoggingEvent addKeyValue(String key, boolean value) { if (this.isEnabled) { addKeyValueInternal(key, value); } @@ -407,9 +407,9 @@ public LoggingEventBuilder addKeyValue(String key, boolean value) { * * @param key Key to associate the provided {@code value} with. * @param value The long value. - * @return The updated {@link LoggingEventBuilder} object. + * @return The updated {@link LoggingEvent} object. */ - public LoggingEventBuilder addKeyValue(String key, long value) { + public LoggingEvent addKeyValue(String key, long value) { if (this.isEnabled) { addKeyValueInternal(key, value); } @@ -421,9 +421,9 @@ public LoggingEventBuilder addKeyValue(String key, long value) { * * @param key String key. * @param valueSupplier String value supplier function. - * @return The updated {@code LoggingEventBuilder} object. + * @return The updated {@code LoggingEvent} object. */ - public LoggingEventBuilder addKeyValue(String key, Supplier valueSupplier) { + public LoggingEvent addKeyValue(String key, Supplier valueSupplier) { if (this.isEnabled && valueSupplier != null) { this.addKeyValue(key, valueSupplier.get()); } @@ -435,9 +435,9 @@ public LoggingEventBuilder addKeyValue(String key, Supplier valueSupplie * that describe the same event. It must not contain any dynamic parts. * * @param eventName The name of the event. - * @return The updated {@code LoggingEventBuilder} object. + * @return The updated {@code LoggingEvent} object. */ - public LoggingEventBuilder setEventName(String eventName) { + public LoggingEvent setEventName(String eventName) { this.eventName = eventName; return this; } diff --git a/sdk/clientcore/core/src/main/resources/META-INF/native-image.io.clientcore.core/native-image.properties b/sdk/clientcore/core/src/main/resources/META-INF/native-image.io.clientcore.core/native-image.properties index 68ecf6d625fd..2298920b7620 100644 --- a/sdk/clientcore/core/src/main/resources/META-INF/native-image.io.clientcore.core/native-image.properties +++ b/sdk/clientcore/core/src/main/resources/META-INF/native-image.io.clientcore.core/native-image.properties @@ -20,7 +20,7 @@ Args=\ io.clientcore.core.util.ClientLogger.LogLevel,\ io.clientcore.core.util.Configuration,\ io.clientcore.core.util.implementation.ImplUtils,\ - io.clientcore.core.util.ClientLogger.LoggingEventBuilder,\ + io.clientcore.core.util.ClientLogger.LoggingEvent,\ diff --git a/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java b/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java index c04016837730..0a936e35a6f2 100644 --- a/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java +++ b/sdk/clientcore/core/src/test/java/io/clientcore/core/util/HttpLoggingPolicyTests.java @@ -528,7 +528,7 @@ private void assertResponseLog(Map log, String expectedUri, Resp Long expectedResponseLength = getLength(response.getBody(), response.getHeaders()); assertEquals(expectedResponseLength, (int) log.get("responseContentLength")); - assertInstanceOf(Double.class, log.get("timeToHeadersMs")); + assertInstanceOf(Double.class, log.get("timeToResponseMs")); assertInstanceOf(Double.class, log.get("durationMs")); assertEquals("", log.get("message")); } @@ -546,7 +546,7 @@ private void assertResponseAndExceptionLog(Map log, String expec assertEquals(response.getStatusCode(), log.get("statusCode")); - assertInstanceOf(Double.class, log.get("timeToHeadersMs")); + assertInstanceOf(Double.class, log.get("timeToResponseMs")); assertInstanceOf(Double.class, log.get("durationMs")); assertEquals(error.getMessage(), log.get("exception.message")); assertEquals(error.getClass().getCanonicalName(), log.get("exception.type")); @@ -564,7 +564,7 @@ private void assertExceptionLog(Map log, String expectedUri, Htt assertNull(log.get("statusCode")); assertNull(log.get("responseContentLength")); - assertNull(log.get("timeToHeadersMs")); + assertNull(log.get("timeToResponseMs")); assertInstanceOf(Double.class, log.get("durationMs")); assertEquals(error.getMessage(), log.get("exception.message")); assertEquals(error.getClass().getCanonicalName(), log.get("exception.type")); From 676ff5653c5b3839059d7d2711fdf6f5f28ecd56 Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Mon, 6 Jan 2025 15:36:56 -0800 Subject: [PATCH 8/8] final nits --- .../io/clientcore/core/http/pipeline/HttpLoggingPolicy.java | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java index 55cc757d4a2e..be575faa8ffb 100644 --- a/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java +++ b/sdk/clientcore/core/src/main/java/io/clientcore/core/http/pipeline/HttpLoggingPolicy.java @@ -18,6 +18,8 @@ import java.io.IOException; import java.net.URI; +import java.util.Collections; +import java.util.List; import java.util.Locale; import java.util.Map; import java.util.Set; @@ -32,7 +34,7 @@ */ public class HttpLoggingPolicy implements HttpPipelinePolicy { private static final HttpLogOptions DEFAULT_HTTP_LOG_OPTIONS = new HttpLogOptions(); - private static final Set ALWAYS_ALLOWED_HEADERS = Set.of(TRACEPARENT); + private static final List ALWAYS_ALLOWED_HEADERS = Collections.singletonList(TRACEPARENT); private static final int MAX_BODY_LOG_SIZE = 1024 * 16; private static final String REDACTED_PLACEHOLDER = "REDACTED"; private static final ClientLogger LOGGER = new ClientLogger(HttpLoggingPolicy.class);