ARUHA-2199: fixed timing to be the same for all systems we report;

zalando · Mar 4, 2019 · 1721b14 · 1721b14
1 parent b68a355
commit 1721b14
Showing 1 changed file with 10 additions and 10 deletions.
diff --git a/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java b/src/main/java/org/zalando/nakadi/filters/LoggingFilter.java
@@ -130,39 +130,39 @@ 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)
                 .put("query", requestLogInfo.query)
                 .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,
                 requestLogInfo.query,
                 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));
         }
     }
 }