[#3727]enhance metrics to reflect current process flow (#4012)

apache · Nov 7, 2023 · 2dd9757 · 2dd9757
1 parent ec57988
commit 2dd9757
Show file tree

Hide file tree

Showing 66 changed files with 1,184 additions and 1,961 deletions.
diff --git a/...apache/servicecomb/common/accessLog/core/element/impl/ConfigurableDatetimeAccessItem.java b/...apache/servicecomb/common/accessLog/core/element/impl/ConfigurableDatetimeAccessItem.java
@@ -58,7 +58,7 @@ public ConfigurableDatetimeAccessItem() {
    * @param config the format of configuration is "PATTERN|TIMEZONE|LOCALE" or "PATTERN". It depends on whether the config contains the separator "|"
    */
   public ConfigurableDatetimeAccessItem(String config) {
-    String[] configArr = null;
+    String[] configArr;
     if (config.contains("|")) {
       configArr = splitConfig(config);
     } else {
@@ -91,10 +91,9 @@ public void appendServerFormattedItem(ServerAccessLogEvent accessLogEvent, Strin
 
   @Override
   public void appendClientFormattedItem(InvocationFinishEvent finishEvent, StringBuilder builder) {
-    long milliDuration = (finishEvent.getInvocation().getInvocationStageTrace().getStartSend() -
-        finishEvent.getInvocation().getInvocationStageTrace().getStart()) / 1000_000;
+    long milliDuration = finishEvent.getInvocation().getInvocationStageTrace().calcTotal() / 1000_000;
     doAppendFormattedItem(
-        finishEvent.getInvocation().getInvocationStageTrace().getStartTimeMillis() + milliDuration, builder);
+        finishEvent.getInvocation().getInvocationStageTrace().getStartInMillis() + milliDuration, builder);
   }
 
   private void doAppendFormattedItem(long milliStartTime, StringBuilder builder) {

diff --git a/.../apache/servicecomb/common/accessLog/core/element/impl/DurationMillisecondAccessItem.java b/.../apache/servicecomb/common/accessLog/core/element/impl/DurationMillisecondAccessItem.java
@@ -31,7 +31,6 @@ public void appendServerFormattedItem(ServerAccessLogEvent accessLogEvent, Strin
 
   @Override
   public void appendClientFormattedItem(InvocationFinishEvent finishEvent, StringBuilder builder) {
-    builder.append((finishEvent.getInvocation().getInvocationStageTrace().getFinish() -
-        finishEvent.getInvocation().getInvocationStageTrace().getStartSend()) / 1000_000);
+    builder.append(finishEvent.getInvocation().getInvocationStageTrace().calcTotal() / 1000_000);
   }
 }
diff --git a/...a/org/apache/servicecomb/common/accessLog/core/element/impl/DurationSecondAccessItem.java b/...a/org/apache/servicecomb/common/accessLog/core/element/impl/DurationSecondAccessItem.java
@@ -33,7 +33,6 @@ public void appendServerFormattedItem(ServerAccessLogEvent accessLogEvent, Strin
 
   @Override
   public void appendClientFormattedItem(InvocationFinishEvent finishEvent, StringBuilder builder) {
-    builder.append((finishEvent.getInvocation().getInvocationStageTrace().getFinish() -
-        finishEvent.getInvocation().getInvocationStageTrace().getStartSend()) / 1000_000_000);
+    builder.append(finishEvent.getInvocation().getInvocationStageTrace().calcTotal() / 1000_000_000);
   }
 }
diff --git a/...og/src/test/java/org/apache/servicecomb/common/accessLog/core/AccessLogGeneratorTest.java b/...og/src/test/java/org/apache/servicecomb/common/accessLog/core/AccessLogGeneratorTest.java
@@ -81,10 +81,8 @@ public void testClientLog() {
     InvocationStageTrace stageTrace = Mockito.mock(InvocationStageTrace.class);
     OperationMeta operationMeta = Mockito.mock(OperationMeta.class);
     long startMillisecond = 1416863450581L;
-    when(stageTrace.getStartSend()).thenReturn(0L);
-    when(stageTrace.getStart()).thenReturn(0L);
-    when(stageTrace.getFinish()).thenReturn(0L);
-    when(stageTrace.getStartTimeMillis()).thenReturn(startMillisecond);
+    when(stageTrace.getStartInMillis()).thenReturn(startMillisecond);
+    when(stageTrace.calcTotal()).thenReturn(0L);
     when(invocation.getOperationMeta()).thenReturn(operationMeta);
     when(invocation.getInvocationStageTrace()).thenReturn(stageTrace);
 

diff --git a/...g/apache/servicecomb/common/accessLog/core/element/impl/DatetimeConfigurableItemTest.java b/...g/apache/servicecomb/common/accessLog/core/element/impl/DatetimeConfigurableItemTest.java
@@ -30,10 +30,6 @@
 import org.junit.jupiter.api.Assertions;
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
-import org.junit.jupiter.api.condition.EnabledOnJre;
-import org.junit.jupiter.api.condition.EnabledOnOs;
-import org.junit.jupiter.api.condition.JRE;
-import org.junit.jupiter.api.condition.OS;
 import org.mockito.Mockito;
 
 public class DatetimeConfigurableItemTest {
@@ -58,61 +54,19 @@ public void initStrBuilder() {
 
     when(finishEvent.getInvocation()).thenReturn(invocation);
     when(invocation.getInvocationStageTrace()).thenReturn(invocationStageTrace);
-    when(invocationStageTrace.getStartSend()).thenReturn(0L);
-    when(invocationStageTrace.getStart()).thenReturn(0L);
-    when(invocationStageTrace.getStartTimeMillis()).thenReturn(START_MILLISECOND);
+    when(invocationStageTrace.getStartInMillis()).thenReturn(START_MILLISECOND);
+    when(invocationStageTrace.calcTotal()).thenReturn(0L);
 
     accessLogEvent = new ServerAccessLogEvent();
     accessLogEvent.setMilliStartTime(START_MILLISECOND);
     strBuilder = new StringBuilder();
   }
 
-  @Test
-  @EnabledOnOs({OS.LINUX, OS.WINDOWS})
-  @EnabledOnJre(JRE.JAVA_8)
-  public void serverFormattedElement() {
-    ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem(
-            "EEE, yyyy MMM dd HH:mm:ss zzz|GMT-08|zh-CN");
-    element.appendServerFormattedItem(accessLogEvent, strBuilder);
-    Assertions.assertEquals("星期一, 2014 十一月 24 13:10:50 GMT-08:00", strBuilder.toString());
-  }
-
-  @Test
-  @EnabledOnOs({OS.LINUX, OS.WINDOWS})
-  @EnabledOnJre(JRE.JAVA_8)
-  public void clientFormattedElement() {
-    ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem(
-            "EEE, yyyy MMM dd HH:mm:ss zzz|GMT-08|zh-CN");
-    element.appendClientFormattedItem(finishEvent, strBuilder);
-    Assertions.assertEquals("星期一, 2014 十一月 24 13:10:50 GMT-08:00", strBuilder.toString());
-  }
-
-  @Test
-  @EnabledOnOs({OS.LINUX, OS.WINDOWS})
-  @EnabledOnJre(JRE.JAVA_8)
-  public void serverFormattedElementOnNoPattern() {
-    ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem(
-            "|GMT+08|zh-CN");
-
-    element.appendServerFormattedItem(accessLogEvent, strBuilder);
-    Assertions.assertEquals("星期二, 25 十一月 2014 05:10:50 GMT+08:00", strBuilder.toString());
-  }
-
-  @Test
-  @EnabledOnOs({OS.LINUX, OS.WINDOWS})
-  @EnabledOnJre(JRE.JAVA_8)
-  public void clientFormattedElementOnNoPattern() {
-    ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem(
-            "|GMT+08|zh-CN");
-
-    element.appendClientFormattedItem(finishEvent, strBuilder);
-    Assertions.assertEquals("星期二, 25 十一月 2014 05:10:50 GMT+08:00", strBuilder.toString());
-  }
 
   @Test
   public void getFormattedElementOnNoTimezone() {
     ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem(
-            "yyyy/MM/dd zzz||zh-CN");
+        "yyyy/MM/dd zzz||zh-CN");
     SimpleDateFormat simpleDateFormat = new SimpleDateFormat("yyyy/MM/dd zzz", Locale.forLanguageTag("zh-CN"));
     simpleDateFormat.setTimeZone(TimeZone.getDefault());
 
@@ -123,7 +77,7 @@ public void getFormattedElementOnNoTimezone() {
   @Test
   public void clientFormattedElementOnNoTimezone() {
     ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem(
-            "yyyy/MM/dd zzz||zh-CN");
+        "yyyy/MM/dd zzz||zh-CN");
     SimpleDateFormat simpleDateFormat = new SimpleDateFormat("yyyy/MM/dd zzz", Locale.forLanguageTag("zh-CN"));
     simpleDateFormat.setTimeZone(TimeZone.getDefault());
 
@@ -134,7 +88,7 @@ public void clientFormattedElementOnNoTimezone() {
   @Test
   public void serverFormattedElementOnNoLocale() {
     ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem(
-            "EEE, dd MMM yyyy HH:mm:ss zzz|GMT+08|");
+        "EEE, dd MMM yyyy HH:mm:ss zzz|GMT+08|");
 
     element.appendServerFormattedItem(accessLogEvent, strBuilder);
     Assertions.assertEquals("Tue, 25 Nov 2014 05:10:50 GMT+08:00", strBuilder.toString());
@@ -143,7 +97,7 @@ public void serverFormattedElementOnNoLocale() {
   @Test
   public void clientFormattedElementOnNoLocale() {
     ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem(
-            "EEE, dd MMM yyyy HH:mm:ss zzz|GMT+08|");
+        "EEE, dd MMM yyyy HH:mm:ss zzz|GMT+08|");
 
     element.appendClientFormattedItem(finishEvent, strBuilder);
     Assertions.assertEquals("Tue, 25 Nov 2014 05:10:50 GMT+08:00", strBuilder.toString());
@@ -152,9 +106,9 @@ public void clientFormattedElementOnNoLocale() {
   @Test
   public void serverFormattedElementOnNoConfig() {
     ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem(
-            "||");
+        "||");
     SimpleDateFormat simpleDateFormat = new SimpleDateFormat(ConfigurableDatetimeAccessItem.DEFAULT_DATETIME_PATTERN,
-            Locale.US);
+        Locale.US);
     simpleDateFormat.setTimeZone(TimeZone.getDefault());
 
     element.appendServerFormattedItem(accessLogEvent, strBuilder);
@@ -164,9 +118,9 @@ public void serverFormattedElementOnNoConfig() {
   @Test
   public void clientFormattedElementOnNoConfig() {
     ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem(
-            "||");
+        "||");
     SimpleDateFormat simpleDateFormat = new SimpleDateFormat(ConfigurableDatetimeAccessItem.DEFAULT_DATETIME_PATTERN,
-            Locale.US);
+        Locale.US);
     simpleDateFormat.setTimeZone(TimeZone.getDefault());
 
     element.appendClientFormattedItem(finishEvent, strBuilder);

diff --git a/...rg/apache/servicecomb/common/accessLog/core/element/impl/DurationMillisecondItemTest.java b/...rg/apache/servicecomb/common/accessLog/core/element/impl/DurationMillisecondItemTest.java
@@ -50,8 +50,7 @@ public void initStrBuilder() {
 
     when(finishEvent.getInvocation()).thenReturn(invocation);
     when(invocation.getInvocationStageTrace()).thenReturn(invocationStageTrace);
-    when(invocationStageTrace.getStartSend()).thenReturn(0L);
-    when(invocationStageTrace.getFinish()).thenReturn(1000_000L);
+    when(invocationStageTrace.calcTotal()).thenReturn(1000_000L);
 
     accessLogEvent = new ServerAccessLogEvent();
     accessLogEvent.setMilliStartTime(1L);

diff --git a/...ava/org/apache/servicecomb/common/accessLog/core/element/impl/DurationSecondItemTest.java b/...ava/org/apache/servicecomb/common/accessLog/core/element/impl/DurationSecondItemTest.java
@@ -50,7 +50,7 @@ public void initStrBuilder() {
 
     when(finishEvent.getInvocation()).thenReturn(invocation);
     when(invocation.getInvocationStageTrace()).thenReturn(invocationStageTrace);
-    when(invocationStageTrace.getStartSend()).thenReturn(1000_000L);
+    when(invocationStageTrace.calcTotal()).thenReturn(1L);
 
     accessLogEvent = new ServerAccessLogEvent();
     accessLogEvent.setMilliStartTime(1L);
@@ -66,7 +66,7 @@ public void serverFormattedElementOn999ms() {
 
   @Test
   public void clientFormattedElementOn999ms() {
-    when(invocationStageTrace.getFinish()).thenReturn(1000_000_000L);
+    when(invocationStageTrace.calcTotal()).thenReturn(0L);
     ELEMENT.appendClientFormattedItem(finishEvent, strBuilder);
     Assertions.assertEquals("0", strBuilder.toString());
   }
@@ -80,7 +80,7 @@ public void serverFormattedElementOn1000ms() {
 
   @Test
   public void clientFormattedElementOn1000ms() {
-    when(invocationStageTrace.getFinish()).thenReturn(1001_000_000L);
+    when(invocationStageTrace.calcTotal()).thenReturn(1000_000_000L);
     ELEMENT.appendClientFormattedItem(finishEvent, strBuilder);
     Assertions.assertEquals("1", strBuilder.toString());
   }
@@ -94,7 +94,7 @@ public void serverFormattedElementOn1001ms() {
 
   @Test
   public void clientFormattedElementOn1001ms() {
-    when(invocationStageTrace.getFinish()).thenReturn(1002_000_000L);
+    when(invocationStageTrace.calcTotal()).thenReturn(1000_000_000L);
     ELEMENT.appendClientFormattedItem(finishEvent, strBuilder);
     Assertions.assertEquals("1", strBuilder.toString());
   }

diff --git a/...mon-rest/src/main/java/org/apache/servicecomb/common/rest/RestProducerInvocationFlow.java b/...mon-rest/src/main/java/org/apache/servicecomb/common/rest/RestProducerInvocationFlow.java
@@ -53,34 +53,41 @@ protected Invocation sendCreateInvocationException(Throwable throwable) {
           requestEx.getRequestURI(), e);
     }
 
-    flushResponse("UNKNOWN_OPERATION");
+    flushResponse(null);
     return null;
   }
 
   @Override
   protected void sendResponse(Invocation invocation, Response response) {
+    invocation.getInvocationStageTrace().startProviderSendResponse();
     if (isDownloadFileResponseType(invocation, response)) {
       responseEx.sendPart(PartUtils.getSinglePart(null, response.getResult()))
-          .whenComplete((r, e) -> flushResponse(invocation.getMicroserviceQualifiedName()));
+          .whenComplete((r, e) -> flushResponse(invocation));
       return;
     }
 
-    flushResponse(invocation.getMicroserviceQualifiedName());
+    flushResponse(invocation);
   }
 
-  private void flushResponse(String operationName) {
+  private void flushResponse(Invocation invocation) {
     try {
       responseEx.flushBuffer();
     } catch (Throwable flushException) {
       LOGGER.error("Failed to flush rest response, operation:{}, request uri:{}",
-          operationName, requestEx.getRequestURI(), flushException);
+          invocation == null ? "NA" :
+              invocation.getMicroserviceQualifiedName(), requestEx.getRequestURI(), flushException);
     }
 
     try {
       requestEx.getAsyncContext().complete();
     } catch (Throwable completeException) {
       LOGGER.error("Failed to complete async rest response, operation:{}, request uri:{}",
-          operationName, requestEx.getRequestURI(), completeException);
+          invocation == null ? "NA" :
+              invocation.getMicroserviceQualifiedName(), requestEx.getRequestURI(), completeException);
+    }
+
+    if (invocation != null) {
+      invocation.getInvocationStageTrace().finishProviderSendResponse();
     }
   }
 }
diff --git a/...st/src/main/java/org/apache/servicecomb/common/rest/codec/param/BodyProcessorCreator.java b/...st/src/main/java/org/apache/servicecomb/common/rest/codec/param/BodyProcessorCreator.java
@@ -62,8 +62,8 @@
 import jakarta.ws.rs.core.MediaType;
 import jakarta.ws.rs.core.Response.Status;
 
-@SuppressWarnings("rawtypes")
 public class BodyProcessorCreator implements ParamValueProcessorCreator<RequestBody> {
+
   private static final Logger LOGGER = LoggerFactory.getLogger(BodyProcessorCreator.class);
 
   public static final String REQUEST_BODY_NAME = "X_REQUEST";
@@ -74,12 +74,12 @@ public class BodyProcessorCreator implements ParamValueProcessorCreator<RequestB
 
   private static final JavaType OBJECT_TYPE = SimpleType.constructUnsafe(Object.class);
 
-  // This configuration is used for temporary use only. Do not use it if you are sure how it works. And may be deleted in future.
-  private static final boolean decodeAsObject = LegacyPropertyFactory
-      .getBooleanProperty("servicecomb.rest.parameter.decodeAsObject", false);
-
   private static final Object LOCK = new Object();
 
+  // This configuration is used for temporary use only.
+  // Do not use it if you are sure how it works. And may be deleted in the future.
+  public static final String PARAM_DECODE_AS_OBJECT = "servicecomb.rest.parameter.decodeAsObject";
+
   public static class BodyProcessor implements ParamValueProcessor {
     // Producer target type. For consumer, is null.
     protected JavaType targetType;
@@ -201,7 +201,7 @@ private Object getValueImpl(HttpServletRequest request) throws IOException {
         ObjectReader reader = serialViewClass != null
             ? RestObjectMapperFactory.getRestObjectMapper().readerWithView(serialViewClass)
             : RestObjectMapperFactory.getRestObjectMapper().reader();
-        if (decodeAsObject) {
+        if (decodeAsObject()) {
           return reader.forType(OBJECT_TYPE).readValue(inputStream);
         }
         return reader.forType(targetType == null ? OBJECT_TYPE : targetType)
@@ -216,6 +216,11 @@ private Object getValueImpl(HttpServletRequest request) throws IOException {
       }
     }
 
+    private boolean decodeAsObject() {
+      return LegacyPropertyFactory
+          .getBooleanProperty(PARAM_DECODE_AS_OBJECT, false);
+    }
+
     private String validContentType(String type) {
       if (StringUtils.isEmpty(type)) {
         if (supportedContentTypes.size() == 0) {

diff --git a/.../src/main/java/org/apache/servicecomb/common/rest/filter/inner/RestServerCodecFilter.java b/.../src/main/java/org/apache/servicecomb/common/rest/filter/inner/RestServerCodecFilter.java
@@ -93,12 +93,14 @@ protected CompletableFuture<Response> invokeNext(Invocation invocation, FilterNo
   }
 
   protected void decodeRequest(Invocation invocation) {
+    invocation.getInvocationStageTrace().startProviderDecodeRequest();
     HttpServletRequestEx requestEx = invocation.getRequestEx();
 
     OperationMeta operationMeta = invocation.getOperationMeta();
     RestOperationMeta restOperationMeta = operationMeta.getExtData(RestConst.SWAGGER_REST_OPERATION);
     Map<String, Object> swaggerArguments = RestCodec.restToArgs(requestEx, restOperationMeta);
     invocation.setSwaggerArguments(swaggerArguments);
+    invocation.getInvocationStageTrace().finishProviderDecodeRequest();
   }
 
   protected CompletableFuture<Response> encodeResponse(Invocation invocation, Response response) {
@@ -113,7 +115,8 @@ protected CompletableFuture<Response> encodeResponse(Invocation invocation, Resp
     HttpServletResponseEx responseEx = transportContext.getResponseEx();
     boolean download = isDownloadFileResponseType(invocation, response);
 
-    return encodeResponse(response, download, produceProcessor, responseEx);
+    return encodeResponse(response, download, produceProcessor, responseEx)
+        .whenComplete((r, e) -> invocation.onEncodeResponseFinish());
   }
 
   public static CompletableFuture<Response> encodeResponse(Response response, boolean download,

diff --git a/.../test/java/org/apache/servicecomb/common/rest/codec/param/TestCookieProcessorCreator.java b/.../test/java/org/apache/servicecomb/common/rest/codec/param/TestCookieProcessorCreator.java
@@ -18,13 +18,24 @@
 package org.apache.servicecomb.common.rest.codec.param;
 
 import org.apache.servicecomb.common.rest.codec.param.CookieProcessorCreator.CookieProcessor;
+import org.apache.servicecomb.foundation.common.LegacyPropertyFactory;
 import org.junit.jupiter.api.Assertions;
+import org.junit.jupiter.api.BeforeAll;
 import org.junit.jupiter.api.Test;
+import org.mockito.Mockito;
+import org.springframework.core.env.Environment;
 
 import io.swagger.v3.oas.models.media.Schema;
 import io.swagger.v3.oas.models.parameters.CookieParameter;
 
 public class TestCookieProcessorCreator {
+  static Environment environment = Mockito.mock(Environment.class);
+
+  @BeforeAll
+  public static void beforeClass() {
+    LegacyPropertyFactory.setEnvironment(environment);
+  }
+
   @Test
   public void testCreate() {
     ParamValueProcessorCreator creator =