This is an automated email from the ASF dual-hosted git repository.
wujimin pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/servicecomb-java-chassis.git
The following commit(s) were added to refs/heads/master by this push:
new 6819a27 [SCB-1208] improve slow invocation logger: log remote address
6819a27 is described below
commit 6819a270d217547c6eaadd0e5ab2aeb8a7e59be7
Author: wujimin <wuji...@huawei.com>
AuthorDate: Tue Mar 19 12:31:43 2019 +0800
[SCB-1208] improve slow invocation logger: log remote address
---
.../metrics/core/publish/SlowInvocationLogger.java | 18 ++++++++++++++++
.../core/publish/TestSlowInvocationLogger.java | 25 +++++++++++++++++++---
2 files changed, 40 insertions(+), 3 deletions(-)
diff --git
a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/publish/SlowInvocationLogger.java
b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/publish/SlowInvocationLogger.java
index f042120..0283b50 100644
---
a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/publish/SlowInvocationLogger.java
+++
b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/publish/SlowInvocationLogger.java
@@ -20,11 +20,13 @@ import java.util.concurrent.TimeUnit;
import org.apache.servicecomb.common.rest.RestConst;
import org.apache.servicecomb.common.rest.definition.RestOperationMeta;
+import org.apache.servicecomb.core.Endpoint;
import org.apache.servicecomb.core.Invocation;
import org.apache.servicecomb.core.SCBEngine;
import org.apache.servicecomb.core.definition.OperationConfig;
import org.apache.servicecomb.core.event.InvocationFinishEvent;
import org.apache.servicecomb.core.invocation.InvocationStageTrace;
+import org.apache.servicecomb.foundation.vertx.http.HttpServletRequestEx;
import org.apache.servicecomb.swagger.invocation.Response;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@@ -62,6 +64,16 @@ public class SlowInvocationLogger {
logSlowConsumer(invocation, event.getResponse(), operationConfig);
}
+ private String collectClientAddress(Invocation invocation) {
+ HttpServletRequestEx requestEx = invocation.getRequestEx();
+ return requestEx == null ? "unknown" : requestEx.getRemoteAddr() + ":" +
requestEx.getRemotePort();
+ }
+
+ private String collectTargetAddress(Invocation invocation) {
+ Endpoint endpoint = invocation.getEndpoint();
+ return endpoint == null ? "unknown" : endpoint.getEndpoint();
+ }
+
private String formatTime(double doubleNano) {
long micros = TimeUnit.NANOSECONDS.toMicros((long) doubleNano);
return micros / 1000 + "." + micros % 1000;
@@ -74,6 +86,7 @@ public class SlowInvocationLogger {
+ "slow({} ms) invocation, {}:\n"
+ " http method: {}\n"
+ " url : {}\n"
+ + " client : {}\n"
+ " status code: {}\n"
+ " total : {} ms\n"
+ " prepare : {} ms\n"
@@ -88,6 +101,7 @@ public class SlowInvocationLogger {
invocation.getInvocationQualifiedName(),
restOperationMeta.getHttpMethod(),
restOperationMeta.getAbsolutePath(),
+ collectClientAddress(invocation),
response.getStatusCode(),
formatTime(stageTrace.calcTotalTime()),
formatTime(stageTrace.calcInvocationPrepareTime()),
@@ -108,6 +122,7 @@ public class SlowInvocationLogger {
+ "slow({} ms) invocation, {}:\n"
+ " http method: {}\n"
+ " url : {}\n"
+ + " server : {}\n"
+ " status code: {}\n"
+ " total : {} ms\n"
+ " prepare : {} ms\n"
@@ -124,6 +139,7 @@ public class SlowInvocationLogger {
invocation.getInvocationQualifiedName(),
restOperationMeta.getHttpMethod(),
restOperationMeta.getAbsolutePath(),
+ collectTargetAddress(invocation),
response.getStatusCode(),
formatTime(stageTrace.calcTotalTime()),
formatTime(stageTrace.calcInvocationPrepareTime()),
@@ -146,6 +162,7 @@ public class SlowInvocationLogger {
+ "slow({} ms) invocation, {}:\n"
+ " http method: {}\n"
+ " url : {}\n"
+ + " server : {}\n"
+ " status code: {}\n"
+ " total : {} ms\n"
+ " prepare : {} ms\n"
@@ -166,6 +183,7 @@ public class SlowInvocationLogger {
invocation.getInvocationQualifiedName(),
restOperationMeta.getHttpMethod(),
restOperationMeta.getAbsolutePath(),
+ collectTargetAddress(invocation),
response.getStatusCode(),
formatTime(stageTrace.calcTotalTime()),
formatTime(stageTrace.calcInvocationPrepareTime()),
diff --git
a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestSlowInvocationLogger.java
b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestSlowInvocationLogger.java
index fb7c5eb..02308cc 100644
---
a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestSlowInvocationLogger.java
+++
b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestSlowInvocationLogger.java
@@ -18,6 +18,7 @@ package org.apache.servicecomb.metrics.core.publish;
import org.apache.servicecomb.common.rest.RestConst;
import org.apache.servicecomb.common.rest.definition.RestOperationMeta;
+import org.apache.servicecomb.core.Endpoint;
import org.apache.servicecomb.core.Invocation;
import org.apache.servicecomb.core.SCBEngine;
import org.apache.servicecomb.core.definition.OperationConfig;
@@ -26,6 +27,7 @@ import
org.apache.servicecomb.core.event.InvocationFinishEvent;
import org.apache.servicecomb.core.invocation.InvocationStageTrace;
import org.apache.servicecomb.foundation.test.scaffolding.config.ArchaiusUtils;
import org.apache.servicecomb.foundation.test.scaffolding.log.LogCollector;
+import org.apache.servicecomb.foundation.vertx.http.HttpServletRequestEx;
import org.apache.servicecomb.swagger.invocation.Response;
import org.junit.After;
import org.junit.Assert;
@@ -102,9 +104,13 @@ public class TestSlowInvocationLogger {
}
@Test
- public void consumerSlow() {
+ public void consumerSlow(@Mocked Endpoint endpoint) {
new Expectations() {
{
+ invocation.getEndpoint();
+ result = endpoint;
+ endpoint.getEndpoint();
+ result = "rest://1.1.1.1:1234";
invocation.isConsumer();
result = true;
operationMeta.getExtData(RestConst.SWAGGER_REST_OPERATION);
@@ -123,6 +129,7 @@ public class TestSlowInvocationLogger {
+ "slow(0 ms) invocation, null:\n"
+ " http method: null\n"
+ " url : null\n"
+ + " server : rest://1.1.1.1:1234\n"
+ " status code: 0\n"
+ " total : 0.0 ms\n"
+ " prepare : 0.0 ms\n"
@@ -139,9 +146,13 @@ public class TestSlowInvocationLogger {
}
@Test
- public void edgeSlow() {
+ public void edgeSlow(@Mocked Endpoint endpoint) {
new Expectations() {
{
+ invocation.getEndpoint();
+ result = endpoint;
+ endpoint.getEndpoint();
+ result = "rest://1.1.1.1:1234";
invocation.isConsumer();
result = true;
invocation.isEdge();
@@ -162,6 +173,7 @@ public class TestSlowInvocationLogger {
+ "slow(0 ms) invocation, null:\n"
+ " http method: null\n"
+ " url : null\n"
+ + " server : rest://1.1.1.1:1234\n"
+ " status code: 0\n"
+ " total : 0.0 ms\n"
+ " prepare : 0.0 ms\n"
@@ -182,9 +194,15 @@ public class TestSlowInvocationLogger {
}
@Test
- public void producerSlow() {
+ public void producerSlow(@Mocked HttpServletRequestEx requestEx) {
new Expectations() {
{
+ invocation.getRequestEx();
+ result = requestEx;
+ requestEx.getRemoteAddr();
+ result = "1.1.1.1";
+ requestEx.getRemotePort();
+ result = 1234;
invocation.isConsumer();
result = false;
operationMeta.getExtData(RestConst.SWAGGER_REST_OPERATION);
@@ -203,6 +221,7 @@ public class TestSlowInvocationLogger {
+ "slow(0 ms) invocation, null:\n"
+ " http method: null\n"
+ " url : null\n"
+ + " client : 1.1.1.1:1234\n"
+ " status code: 0\n"
+ " total : 0.0 ms\n"
+ " prepare : 0.0 ms\n"
