From 86438e96157f1466a9adba037c20227a4e0ce393 Mon Sep 17 00:00:00 2001 From: Pavel Popov Date: Tue, 24 Jul 2018 15:06:02 +0300 Subject: [PATCH] Add more logs for http requests (#58) * Add more logs in http requests * Switch log level to debug --- pom.xml | 2 +- .../logging/HttpLoggingInterceptor.java | 276 ++++++++++++++++++ .../rbkmoney/hooker/service/PostSender.java | 5 + 3 files changed, 282 insertions(+), 1 deletion(-) create mode 100644 src/main/java/com/rbkmoney/hooker/logging/HttpLoggingInterceptor.java diff --git a/pom.xml b/pom.xml index b1f3b32..678a97b 100644 --- a/pom.xml +++ b/pom.xml @@ -4,7 +4,7 @@ 4.0.0 hooker - 2.0.13-SNAPSHOT + 2.0.14-SNAPSHOT jar hooker diff --git a/src/main/java/com/rbkmoney/hooker/logging/HttpLoggingInterceptor.java b/src/main/java/com/rbkmoney/hooker/logging/HttpLoggingInterceptor.java new file mode 100644 index 0000000..7842b7d --- /dev/null +++ b/src/main/java/com/rbkmoney/hooker/logging/HttpLoggingInterceptor.java @@ -0,0 +1,276 @@ +package com.rbkmoney.hooker.logging; + +import okhttp3.*; +import okhttp3.internal.http.HttpHeaders; +import okio.Buffer; +import okio.BufferedSource; +import org.slf4j.LoggerFactory; + +import java.io.EOFException; +import java.io.IOException; +import java.nio.charset.Charset; +import java.util.concurrent.TimeUnit; + +/** + * An OkHttp interceptor which logs request and response information. Can be applied as an + * {@linkplain OkHttpClient#interceptors() application interceptor} or as a {@linkplain + * OkHttpClient#networkInterceptors() network interceptor}.

The format of the logs created by + * this class should not be considered stable and may change slightly between releases. If you need + * a stable logging format, use your own interceptor. + */ +public final class HttpLoggingInterceptor implements Interceptor { + private static final Charset UTF8 = Charset.forName("UTF-8"); + private static final org.slf4j.Logger log = LoggerFactory.getLogger(HttpLoggingInterceptor.class); + + public enum Level { + /** + * No logs. + */ + NONE, + /** + * Logs request and response lines. + *

+ *

Example: + * 

{@code
+         * --> POST /greeting http/1.1 (3-byte body)
+         *
+         * <-- 200 OK (22ms, 6-byte body)
+         * }
+ */ + BASIC, + /** + * Logs request and response lines and their respective headers. + *

+ *

Example: + * 

{@code
+         * --> POST /greeting http/1.1
+         * Host: example.com
+         * Content-Type: plain/text
+         * Content-Length: 3
+         * --> END POST
+         *
+         * <-- 200 OK (22ms)
+         * Content-Type: plain/text
+         * Content-Length: 6
+         * <-- END HTTP
+         * }
+ */ + HEADERS, + /** + * Logs request and response lines and their respective headers and bodies (if present). + *

+ *

Example: + * 

{@code
+         * --> POST /greeting http/1.1
+         * Host: example.com
+         * Content-Type: plain/text
+         * Content-Length: 3
+         *
+         * Hi?
+         * --> END POST
+         *
+         * <-- 200 OK (22ms)
+         * Content-Type: plain/text
+         * Content-Length: 6
+         *
+         * Hello!
+         * <-- END HTTP
+         * }
+ */ + BODY + } + + public interface Logger { + void log(String message); + + /** + * A {@link Logger} defaults output appropriate for the current platform. + */ + Logger DEFAULT = message -> log.debug(message); + } + + public HttpLoggingInterceptor() { + this(Logger.DEFAULT); + } + + public HttpLoggingInterceptor(Logger logger) { + this.logger = logger; + } + + private final Logger logger; + + private volatile Level level = Level.BODY; + + /** + * Change the level at which this interceptor logs. + */ + public HttpLoggingInterceptor setLevel(Level level) { + if (level == null) throw new NullPointerException("level == null. Use Level.NONE instead."); + this.level = level; + return this; + } + + public Level getLevel() { + return level; + } + + @Override + public Response intercept(Chain chain) throws IOException { + Level level = this.level; + + Request request = chain.request(); + if (level == Level.NONE) { + return chain.proceed(request); + } + + boolean logBody = level == Level.BODY; + boolean logHeaders = logBody || level == Level.HEADERS; + + RequestBody requestBody = request.body(); + boolean hasRequestBody = requestBody != null; + + Connection connection = chain.connection(); + StringBuilder message = new StringBuilder("--> \n") + .append(request.method()) + .append(' ').append(request.url()) + .append(connection != null ? " " + connection.protocol() : "").append('\n'); + if (!logHeaders && hasRequestBody) { + message.append(" (").append(requestBody.contentLength()).append("-byte body)").append('\n'); + } + //logger.log(requestStartMessage); + + if (logHeaders) { + if (hasRequestBody) { + // Request body headers are only present when installed as a network interceptor. Force + // them to be included (when available) so there values are known. + if (requestBody.contentType() != null) { + message.append("Content-Type: ").append(requestBody.contentType()).append('\n'); + } + if (requestBody.contentLength() != -1) { + message.append("Content-Length: ").append(requestBody.contentLength()).append('\n'); + } + } + + Headers headers = request.headers(); + for (int i = 0, count = headers.size(); i < count; i++) { + String name = headers.name(i); + // Skip headers from the request body as they are explicitly logged above. + if (!"Authorization".equalsIgnoreCase(name)) { + message.append(name).append(": ").append(headers.value(i)).append('\n'); + } + } + + if (!logBody || !hasRequestBody) { + message.append("\n--> END ").append(request.method()); + } else if (bodyEncoded(request.headers())) { + message.append("\n--> END ").append(request.method()).append(" (encoded body omitted)"); + } else { + message.append('\n'); + Buffer buffer = new Buffer(); + requestBody.writeTo(buffer); + + Charset charset = UTF8; + MediaType contentType = requestBody.contentType(); + if (contentType != null) { + charset = contentType.charset(UTF8); + } + + if (isPlaintext(buffer)) { + message.append(buffer.readString(charset)); + message.append("\n--> END ").append(request.method()) + .append(" (").append(requestBody.contentLength()).append("-byte body)"); + } else { + message.append("\n--> END ").append(request.method()).append(" (binary ") + .append(requestBody.contentLength()).append("-byte body omitted)"); + } + } + } + logger.log(message.toString()); + long startNs = System.nanoTime(); + Response response; + try { + response = chain.proceed(request); + } catch (Exception e) { + logger.log("<-- HTTP FAILED: " + e); + throw e; + } + long tookMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs); + + ResponseBody responseBody = response.body(); + long contentLength = responseBody.contentLength(); + message = new StringBuilder(); + String bodySize = contentLength != -1 ? contentLength + "-byte" : "unknown-length"; + message.append("<-- \n") + .append(response.code()) + .append(response.message().isEmpty() ? "" : " " + response.message()) + .append(' ').append(response.request().url()) + .append(" (").append(tookMs).append("ms").append((!logHeaders ? ", " + bodySize + " body" : "") + ')').append('\n'); + + if (logHeaders) { + Headers headers = response.headers(); + for (int i = 0, count = headers.size(); i < count; i++) { + message.append(headers.name(i)).append(": ").append(headers.value(i)).append('\n'); + } + + if (!logBody || !HttpHeaders.hasBody(response)) { + message.append("\n<-- END HTTP"); + } else if (bodyEncoded(response.headers())) { + message.append("\n<-- END HTTP (encoded body omitted)"); + } else { + message.append('\n'); + BufferedSource source = responseBody.source(); + source.request(Long.MAX_VALUE); // Buffer the entire body. + Buffer buffer = source.buffer(); + + Charset charset = UTF8; + MediaType contentType = responseBody.contentType(); + if (contentType != null) { + charset = contentType.charset(UTF8); + } + + if (!isPlaintext(buffer)) { + message.append("\n<-- END HTTP (binary ").append(buffer.size()).append("-byte body omitted)"); + return response; + } + + if (contentLength != 0) { + message.append(buffer.clone().readString(charset)); + } + + logger.log(message.append("\n<-- END HTTP (").append(buffer.size()).append("-byte body)").toString()); + } + } + + return response; + } + + /** + * Returns true if the body in question probably contains human readable text. Uses a small sample + * of code points to detect unicode control characters commonly used in binary file signatures. + */ + static boolean isPlaintext(Buffer buffer) { + try { + Buffer prefix = new Buffer(); + long byteCount = buffer.size() < 64 ? buffer.size() : 64; + buffer.copyTo(prefix, 0, byteCount); + for (int i = 0; i < 16; i++) { + if (prefix.exhausted()) { + break; + } + int codePoint = prefix.readUtf8CodePoint(); + if (Character.isISOControl(codePoint) && !Character.isWhitespace(codePoint)) { + return false; + } + } + return true; + } catch (EOFException e) { + return false; // Truncated UTF-8 sequence. + } + } + + private boolean bodyEncoded(Headers headers) { + String contentEncoding = headers.get("Content-Encoding"); + return contentEncoding != null && !contentEncoding.equalsIgnoreCase("identity"); + } +} + diff --git a/src/main/java/com/rbkmoney/hooker/service/PostSender.java b/src/main/java/com/rbkmoney/hooker/service/PostSender.java index 166d5b4..da90955 100644 --- a/src/main/java/com/rbkmoney/hooker/service/PostSender.java +++ b/src/main/java/com/rbkmoney/hooker/service/PostSender.java @@ -1,5 +1,6 @@ package com.rbkmoney.hooker.service; +import com.rbkmoney.hooker.logging.HttpLoggingInterceptor; import okhttp3.*; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -17,7 +18,11 @@ public class PostSender { public static final String SIGNATURE_HEADER = "Content-Signature"; public PostSender(@Value("${merchant.callback.timeout}") int timeout) { + HttpLoggingInterceptor httpLoggingInterceptor = new HttpLoggingInterceptor(); + httpLoggingInterceptor.setLevel(HttpLoggingInterceptor.Level.BODY); + this.httpClient = new OkHttpClient.Builder() + .addInterceptor(httpLoggingInterceptor) .connectTimeout(timeout, TimeUnit.SECONDS) .writeTimeout(timeout, TimeUnit.SECONDS) .readTimeout(timeout, TimeUnit.SECONDS)