From 880fd11e9f81593dca13d78f00d685db6d754395 Mon Sep 17 00:00:00 2001 From: vstepanov Date: Fri, 1 Mar 2019 11:31:51 +0100 Subject: [PATCH 1/6] ARUHA-2199: Added open tracing; --- build.gradle | 4 + .../zalando/nakadi/filters/LoggingFilter.java | 121 +++++++++++------- 2 files changed, 78 insertions(+), 47 deletions(-) diff --git a/build.gradle b/build.gradle index 14fefd5522..24b1fc8565 100644 --- a/build.gradle +++ b/build.gradle @@ -168,6 +168,10 @@ dependencies { compile 'org.zalando:twintip-spring-web:1.1.0' compile 'org.json:json:20180130' + // open tracing + compile 'io.opentracing:opentracing-api:0.31.0' + compile 'io.opentracing:opentracing-util:0.31.0' + // tests testCompile 'org.hamcrest:hamcrest-all:1.3' testCompile('junit:junit:4.12') { diff --git a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java index 7826d9330d..89ea02771a 100644 --- a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java +++ b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java @@ -1,12 +1,12 @@ package org.zalando.nakadi.filters; import com.google.common.net.HttpHeaders; +import io.opentracing.util.GlobalTracer; import org.json.JSONObject; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.beans.factory.annotation.Value; -import org.springframework.http.HttpStatus; import org.springframework.stereotype.Component; import org.springframework.web.filter.OncePerRequestFilter; import org.zalando.nakadi.plugin.api.authz.AuthorizationService; @@ -22,6 +22,7 @@ import javax.servlet.http.HttpServletResponse; import java.io.IOException; import java.util.Optional; +import java.util.concurrent.TimeUnit; @Component public class LoggingFilter extends OncePerRequestFilter { @@ -31,7 +32,6 @@ public class LoggingFilter extends OncePerRequestFilter { private final NakadiKpiPublisher nakadiKpiPublisher; private final String accessLogEventType; - private final AuthorizationService authorizationService; @Autowired @@ -43,7 +43,7 @@ public LoggingFilter(final NakadiKpiPublisher nakadiKpiPublisher, this.authorizationService = authorizationService; } - private class RequestLogInfo { + public class RequestLogInfo { private String userAgent; private String user; @@ -55,16 +55,14 @@ private class RequestLogInfo { private String acceptEncoding; private Long requestTime; - private RequestLogInfo(final HttpServletRequest request, final long requestTime) { + public RequestLogInfo(final HttpServletRequest request, final long requestTime) { this.userAgent = Optional.ofNullable(request.getHeader("User-Agent")).orElse("-"); this.user = authorizationService.getSubject().map(Subject::getName).orElse("-"); this.method = request.getMethod(); this.path = request.getRequestURI(); this.query = Optional.ofNullable(request.getQueryString()).map(q -> "?" + q).orElse(""); - this.contentEncoding = Optional.ofNullable(request.getHeader(HttpHeaders.CONTENT_ENCODING)) - .orElse("-"); - this.acceptEncoding = Optional.ofNullable(request.getHeader(HttpHeaders.ACCEPT_ENCODING)) - .orElse("-"); + this.contentEncoding = Optional.ofNullable(request.getHeader(HttpHeaders.CONTENT_ENCODING)).orElse("-"); + this.acceptEncoding = Optional.ofNullable(request.getHeader(HttpHeaders.ACCEPT_ENCODING)).orElse("-"); this.contentLength = request.getContentLengthLong() == -1 ? 0 : request.getContentLengthLong(); this.requestTime = requestTime; } @@ -76,27 +74,17 @@ private class AsyncRequestListener implements AsyncListener { private final RequestLogInfo requestLogInfo; private AsyncRequestListener(final HttpServletRequest request, final HttpServletResponse response, - final long startTime, final String flowId) { + final long startTime, final String flowId) { this.response = response; this.flowId = flowId; this.requestLogInfo = new RequestLogInfo(request, startTime); - ACCESS_LOGGER.info("{} \"{}{}\" \"{}\" \"{}\" {} {}ms \"{}\" \"{}\" {}B", - requestLogInfo.method, - requestLogInfo.path, - requestLogInfo.query, - requestLogInfo.userAgent, - requestLogInfo.user, - HttpStatus.PROCESSING.value(), - 0, - requestLogInfo.contentEncoding, - requestLogInfo.acceptEncoding, - requestLogInfo.contentLength); + logToAccessLog(this.requestLogInfo, this.response.getStatus(), 0L); } private void logOnEvent() { FlowIdUtils.push(this.flowId); - writeToAccessLogAndEventType(this.requestLogInfo, this.response); + logRequest(this.requestLogInfo, this.response.getStatus()); FlowIdUtils.clear(); } @@ -124,7 +112,7 @@ public void onStartAsync(final AsyncEvent event) { @Override protected void doFilterInternal(final HttpServletRequest request, final HttpServletResponse response, final FilterChain filterChain) - throws IOException, ServletException{ + throws IOException, ServletException { final long start = System.currentTimeMillis(); try { //execute request @@ -134,35 +122,74 @@ protected void doFilterInternal(final HttpServletRequest request, request.getAsyncContext().addListener(new AsyncRequestListener(request, response, start, flowId)); } } finally { - if(!request.isAsyncStarted()) { + if (!request.isAsyncStarted()) { final RequestLogInfo requestLogInfo = new RequestLogInfo(request, start); - writeToAccessLogAndEventType(requestLogInfo, response); + logRequest(requestLogInfo, response.getStatus()); } } } - private void writeToAccessLogAndEventType(final RequestLogInfo requestLogInfo, final HttpServletResponse response) { - final long currentTime = System.currentTimeMillis(); - final Long timing = currentTime - requestLogInfo.requestTime; - - ACCESS_LOGGER.info("{} \"{}{}\" \"{}\" \"{}\" {} {}ms \"{}\" \"{}\" {}B", - requestLogInfo.method, - requestLogInfo.path, - requestLogInfo.query, - requestLogInfo.userAgent, - requestLogInfo.user, - response.getStatus(), - timing, - requestLogInfo.contentEncoding, - requestLogInfo.acceptEncoding, - requestLogInfo.contentLength); - nakadiKpiPublisher.publish(accessLogEventType, () -> new JSONObject() - .put("method", requestLogInfo.method) - .put("path", requestLogInfo.path) - .put("query", requestLogInfo.query) - .put("app", requestLogInfo.user) - .put("app_hashed", nakadiKpiPublisher.hash(requestLogInfo.user)) - .put("status_code", response.getStatus()) - .put("response_time_ms", timing)); + private void logRequest(final RequestLogInfo requestLogInfo, final int statusCode) { + final Long timing = System.currentTimeMillis() - requestLogInfo.requestTime; + + logToAccessLog(requestLogInfo, statusCode, timing); + logToNakadi(requestLogInfo, statusCode, timing); + traceRequest(requestLogInfo, statusCode); + } + + private void logToNakadi(final RequestLogInfo requestLogInfo, final int statusCode, final Long timing) { + nakadiKpiPublisher.publish(accessLogEventType, () -> new JSONObject() + .put("method", requestLogInfo.method) + .put("path", requestLogInfo.path) + .put("query", requestLogInfo.query) + .put("app", requestLogInfo.user) + .put("app_hashed", nakadiKpiPublisher.hash(requestLogInfo.user)) + .put("status_code", statusCode) + .put("response_time_ms", timing)); + } + + private void logToAccessLog(final RequestLogInfo requestLogInfo, final int statusCode, final Long timing) { + ACCESS_LOGGER.info("{} \"{}{}\" \"{}\" \"{}\" {} {}ms \"{}\" \"{}\" {}B", + requestLogInfo.method, + requestLogInfo.path, + requestLogInfo.query, + requestLogInfo.userAgent, + requestLogInfo.user, + statusCode, + timing, + requestLogInfo.contentEncoding, + requestLogInfo.acceptEncoding, + requestLogInfo.contentLength); + } + + private void traceRequest(final RequestLogInfo requestLogInfo, final int statusCode) { + if ("POST".equals(requestLogInfo.method) && requestLogInfo.path.startsWith("/event-types/") && + requestLogInfo.path.contains("/events")) { + + final String eventType = requestLogInfo.path.substring(13, requestLogInfo.path.lastIndexOf("/events")); + + String sloBucket = "5K-50K"; + if (requestLogInfo.contentLength < 5000) { + sloBucket = "<5K"; + } else if (requestLogInfo.contentLength > 50000) { + sloBucket = ">50K"; + } + + GlobalTracer.get() + .buildSpan("publish_events") + .withStartTimestamp(TimeUnit.MILLISECONDS.toMicros(requestLogInfo.requestTime)) + .start() + .setTag("app", requestLogInfo.user) + .setTag("event_type", eventType) + .setTag("error", statusCode != 200) + .setTag("http.status_code", statusCode) + .setTag("http.url", requestLogInfo.path + requestLogInfo.query) + .setTag("http.header.content_encoding", requestLogInfo.contentEncoding) + .setTag("http.header.accept_encoding", requestLogInfo.acceptEncoding) + .setTag("http.header.user_agent", requestLogInfo.userAgent) + .setTag("slo_bucket", sloBucket) + .setTag("content_length", requestLogInfo.contentLength) + .finish(); + } } } From d8ad1f52b995586572910b32556faa020722b9e0 Mon Sep 17 00:00:00 2001 From: vstepanov Date: Fri, 1 Mar 2019 11:39:45 +0100 Subject: [PATCH 2/6] ARUHA-2199: reverted class back to private; --- src/main/java/org/zalando/nakadi/filters/LoggingFilter.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java index 89ea02771a..32e7d0f868 100644 --- a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java +++ b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java @@ -43,7 +43,7 @@ public LoggingFilter(final NakadiKpiPublisher nakadiKpiPublisher, this.authorizationService = authorizationService; } - public class RequestLogInfo { + private class RequestLogInfo { private String userAgent; private String user; @@ -55,7 +55,7 @@ public class RequestLogInfo { private String acceptEncoding; private Long requestTime; - public RequestLogInfo(final HttpServletRequest request, final long requestTime) { + private RequestLogInfo(final HttpServletRequest request, final long requestTime) { this.userAgent = Optional.ofNullable(request.getHeader("User-Agent")).orElse("-"); this.user = authorizationService.getSubject().map(Subject::getName).orElse("-"); this.method = request.getMethod(); From c140b6f54ec1113fdf86f8f76a4710f506dcc637 Mon Sep 17 00:00:00 2001 From: vstepanov Date: Fri, 1 Mar 2019 13:46:25 +0100 Subject: [PATCH 3/6] ARUHA-2199: removed magic number; --- src/main/java/org/zalando/nakadi/filters/LoggingFilter.java | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java index 32e7d0f868..d7a0820a05 100644 --- a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java +++ b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java @@ -166,7 +166,8 @@ private void traceRequest(final RequestLogInfo requestLogInfo, final int statusC if ("POST".equals(requestLogInfo.method) && requestLogInfo.path.startsWith("/event-types/") && requestLogInfo.path.contains("/events")) { - final String eventType = requestLogInfo.path.substring(13, requestLogInfo.path.lastIndexOf("/events")); + final String eventType = requestLogInfo.path.substring("/event-types/".length(), + requestLogInfo.path.lastIndexOf("/events")); String sloBucket = "5K-50K"; if (requestLogInfo.contentLength < 5000) { From b68a35514e730d1bd6e520a6ff9b9d71e7ede77d Mon Sep 17 00:00:00 2001 From: vstepanov Date: Fri, 1 Mar 2019 15:22:16 +0100 Subject: [PATCH 4/6] ARUHA-2199: fixed tags; --- src/main/java/org/zalando/nakadi/filters/LoggingFilter.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java index d7a0820a05..f7b7730271 100644 --- a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java +++ b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java @@ -180,9 +180,9 @@ private void traceRequest(final RequestLogInfo requestLogInfo, final int statusC .buildSpan("publish_events") .withStartTimestamp(TimeUnit.MILLISECONDS.toMicros(requestLogInfo.requestTime)) .start() - .setTag("app", requestLogInfo.user) + .setTag("client_id", requestLogInfo.user) .setTag("event_type", eventType) - .setTag("error", statusCode != 200) + .setTag("error", statusCode == 207 || statusCode >= 500) .setTag("http.status_code", statusCode) .setTag("http.url", requestLogInfo.path + requestLogInfo.query) .setTag("http.header.content_encoding", requestLogInfo.contentEncoding) From 1721b1483f45ceddfab21c23d12d99419c3ea996 Mon Sep 17 00:00:00 2001 From: vstepanov Date: Mon, 4 Mar 2019 12:15:42 +0100 Subject: [PATCH 5/6] ARUHA-2199: fixed timing to be the same for all systems we report; --- .../zalando/nakadi/filters/LoggingFilter.java | 20 +++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java index f7b7730271..4ec8bcec0d 100644 --- a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java +++ b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java @@ -130,14 +130,14 @@ protected void doFilterInternal(final HttpServletRequest request, } private void logRequest(final RequestLogInfo requestLogInfo, final int statusCode) { - final Long timing = System.currentTimeMillis() - requestLogInfo.requestTime; + final Long timeSpentMs = System.currentTimeMillis() - requestLogInfo.requestTime; - logToAccessLog(requestLogInfo, statusCode, timing); - logToNakadi(requestLogInfo, statusCode, timing); - traceRequest(requestLogInfo, statusCode); + logToAccessLog(requestLogInfo, statusCode, timeSpentMs); + logToNakadi(requestLogInfo, statusCode, timeSpentMs); + traceRequest(requestLogInfo, statusCode, timeSpentMs); } - private void logToNakadi(final RequestLogInfo requestLogInfo, final int statusCode, final Long timing) { + private void logToNakadi(final RequestLogInfo requestLogInfo, final int statusCode, final Long timeSpentMs) { nakadiKpiPublisher.publish(accessLogEventType, () -> new JSONObject() .put("method", requestLogInfo.method) .put("path", requestLogInfo.path) @@ -145,10 +145,10 @@ private void logToNakadi(final RequestLogInfo requestLogInfo, final int statusCo .put("app", requestLogInfo.user) .put("app_hashed", nakadiKpiPublisher.hash(requestLogInfo.user)) .put("status_code", statusCode) - .put("response_time_ms", timing)); + .put("response_time_ms", timeSpentMs)); } - private void logToAccessLog(final RequestLogInfo requestLogInfo, final int statusCode, final Long timing) { + private void logToAccessLog(final RequestLogInfo requestLogInfo, final int statusCode, final Long timeSpentMs) { ACCESS_LOGGER.info("{} \"{}{}\" \"{}\" \"{}\" {} {}ms \"{}\" \"{}\" {}B", requestLogInfo.method, requestLogInfo.path, @@ -156,13 +156,13 @@ private void logToAccessLog(final RequestLogInfo requestLogInfo, final int statu requestLogInfo.userAgent, requestLogInfo.user, statusCode, - timing, + timeSpentMs, requestLogInfo.contentEncoding, requestLogInfo.acceptEncoding, requestLogInfo.contentLength); } - private void traceRequest(final RequestLogInfo requestLogInfo, final int statusCode) { + private void traceRequest(final RequestLogInfo requestLogInfo, final int statusCode, final Long timeSpentMs) { if ("POST".equals(requestLogInfo.method) && requestLogInfo.path.startsWith("/event-types/") && requestLogInfo.path.contains("/events")) { @@ -190,7 +190,7 @@ private void traceRequest(final RequestLogInfo requestLogInfo, final int statusC .setTag("http.header.user_agent", requestLogInfo.userAgent) .setTag("slo_bucket", sloBucket) .setTag("content_length", requestLogInfo.contentLength) - .finish(); + .finish(TimeUnit.MILLISECONDS.toMicros(requestLogInfo.requestTime + timeSpentMs)); } } } From dbae4615dc693b826bf4d8605c58161cadf62e51 Mon Sep 17 00:00:00 2001 From: vstepanov Date: Mon, 4 Mar 2019 13:42:03 +0100 Subject: [PATCH 6/6] ARUHA-2199: fixed status code 102 reporting; check for null; --- .../java/org/zalando/nakadi/filters/LoggingFilter.java | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java index 4ec8bcec0d..77b0c732bd 100644 --- a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java +++ b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java @@ -7,6 +7,7 @@ import org.slf4j.LoggerFactory; import org.springframework.beans.factory.annotation.Autowired; import org.springframework.beans.factory.annotation.Value; +import org.springframework.http.HttpStatus; import org.springframework.stereotype.Component; import org.springframework.web.filter.OncePerRequestFilter; import org.zalando.nakadi.plugin.api.authz.AuthorizationService; @@ -79,7 +80,7 @@ private AsyncRequestListener(final HttpServletRequest request, final HttpServlet this.flowId = flowId; this.requestLogInfo = new RequestLogInfo(request, startTime); - logToAccessLog(this.requestLogInfo, this.response.getStatus(), 0L); + logToAccessLog(this.requestLogInfo, HttpStatus.PROCESSING.value(), 0L); } private void logOnEvent() { @@ -163,8 +164,8 @@ private void logToAccessLog(final RequestLogInfo requestLogInfo, final int statu } private void traceRequest(final RequestLogInfo requestLogInfo, final int statusCode, final Long timeSpentMs) { - if ("POST".equals(requestLogInfo.method) && requestLogInfo.path.startsWith("/event-types/") && - requestLogInfo.path.contains("/events")) { + if (requestLogInfo.path != null && "POST".equals(requestLogInfo.method) && + requestLogInfo.path.startsWith("/event-types/") && requestLogInfo.path.contains("/events")) { final String eventType = requestLogInfo.path.substring("/event-types/".length(), requestLogInfo.path.lastIndexOf("/events"));