[ https://issues.apache.org/jira/browse/SCB-293?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16340781#comment-16340781 ]
Yang Bo commented on SCB-293: ----------------------------- This is due to the asynchronous reporting of metrics from client to zipkin server. After the client side generated the metrics, it's not guaranteed to be immediately reported to the server. From the logs, we see that there is a POST request happens later than the GET request. {color:#333333}------ Jan 22, 2018 5:06:39 AM okhttp3.mockwebserver.MockWebServer$3 processOneRequest INFO: MockWebServer[32871] received request: GET /api/v2/trace/ebc2a9a79ef653e3 HTTP/1.1 and responded: HTTP/1.1 200 OK Jan 22, 2018 5:06:39 AM okhttp3.mockwebserver.MockWebServer$3 processOneRequest INFO: MockWebServer[32871] received request: POST /api/v2/spans HTTP/1.1 and responded: HTTP/1.1 202 OK{color} {color:#333333}------{color} {color:#333333}We can wait for like 5 seconds before quering to let the reporter finish their job, but there is no way to guarantee that.{color} > trace integration test has small probability lost data. > ------------------------------------------------------- > > Key: SCB-293 > URL: https://issues.apache.org/jira/browse/SCB-293 > Project: Apache ServiceComb > Issue Type: Bug > Components: Java-Chassis > Reporter: wujimin > Assignee: Yang Bo > Priority: Major > > 05:06:38,161 [ebc2a9a79ef653e3/5c77469686c84d3f/1b6b1907ad44e15d] INFO > [pool-2-thread-3] tracing.TracedPojoImpl (TracedPojoImpl.java:31) - in /pojo > Jan 22, 2018 5:06:38 AM okhttp3.mockwebserver.MockWebServer$3 > processOneRequest > INFO: MockWebServer[32871] received request: POST /api/v2/spans HTTP/1.1 and > responded: HTTP/1.1 202 OK > 05:06:39,314 [//] INFO [main] tracing.TracingTestBase > (TracingTestBase.java:73) - Received log: 05:06:37,269 > [ebc2a9a79ef653e3/ebc2a9a79ef653e3/] INFO [pool-2-thread-1] > tracing.SomeTracedController (SomeTracedController.java:47) - in /hello > 05:06:39,315 [//] INFO [main] tracing.TracingTestBase > (TracingTestBase.java:73) - Received log: 05:06:37,293 > [ebc2a9a79ef653e3/62b00f7ba98331ac/ebc2a9a79ef653e3] INFO [pool-2-thread-1] > tracing.SlowRepoImpl (SlowRepoImpl.java:34) - in /crawl > 05:06:39,315 [//] INFO [main] tracing.TracingTestBase > (TracingTestBase.java:73) - Received log: 05:06:37,929 > [ebc2a9a79ef653e3/1b6b1907ad44e15d/ebc2a9a79ef653e3] INFO [pool-2-thread-2] > tracing.TracedJaxrsController (TracedJaxrsController.java:51) - in /bonjour > 05:06:39,316 [//] INFO [main] tracing.TracingTestBase > (TracingTestBase.java:73) - Received log: 05:06:38,161 > [ebc2a9a79ef653e3/5c77469686c84d3f/1b6b1907ad44e15d] INFO [pool-2-thread-3] > tracing.TracedPojoImpl (TracedPojoImpl.java:31) - in /pojo > 05:06:39,317 [//] INFO [main] tracing.TracingTestBase > (TracingTestBase.java:79) - rest > url:http://localhost:32871/api/v2/trace/\{traceId} > 05:06:39,322 [//] INFO [main] tracing.TracingTestBase > (TracingTestBase.java:84) - Received trace json: > [\{"traceId":"ebc2a9a79ef653e3","parentId":"ebc2a9a79ef653e3","id":"62b00f7ba98331ac","name":"crawl","timestamp":1516597597292328,"duration":24877,"localEndpoint":{"serviceName":"tracing-service","ipv4":"10.20.0.41"},"tags":\{"call.path":"public > abstract java.lang.String > org.apache.servicecomb.tests.tracing.SlowRepo.crawl() throws > java.lang.InterruptedException"}},\{"traceId":"ebc2a9a79ef653e3","parentId":"1b6b1907ad44e15d","id":"5c77469686c84d3f","kind":"SERVER","name":"post","timestamp":1516597598138483,"duration":27967,"localEndpoint":{"serviceName":"tracing-service","ipv4":"10.20.0.41"},"tags":\{"http.path":"/pojo"}}] > 05:06:39,326 [//] INFO [main] tracing.TracingTestBase > (TracingTestBase.java:89) - Received value public abstract java.lang.String > org.apache.servicecomb.tests.tracing.SlowRepo.crawl() throws > java.lang.InterruptedException > 05:06:39,327 [//] INFO [main] tracing.TracingTestBase > (TracingTestBase.java:89) - Received value /pojo > 05:06:39,327 [//] INFO [main] tracing.TracingTestBase > (TracingTestBase.java:90) - values: /hello,public abstract java.lang.String > org.apache.servicecomb.tests.tracing.SlowRepo.crawl() throws > java.lang.InterruptedException,/bonjour,/pojo > Jan 22, 2018 5:06:39 AM okhttp3.mockwebserver.MockWebServer$3 > processOneRequest > INFO: MockWebServer[32871] received request: GET > /api/v2/trace/ebc2a9a79ef653e3 HTTP/1.1 and responded: HTTP/1.1 200 OK > Jan 22, 2018 5:06:39 AM okhttp3.mockwebserver.MockWebServer$3 > processOneRequest > INFO: MockWebServer[32871] received request: POST /api/v2/spans HTTP/1.1 and > responded: HTTP/1.1 202 OK > Jan 22, 2018 5:06:39 AM okhttp3.mockwebserver.MockWebServer$2 > acceptConnections > INFO: MockWebServer[32871] done accepting connections: Socket closed > Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 12.203 sec > <<< FAILURE! - in > org.apache.servicecomb.tests.tracing.ZipkinTracingIntegrationTest > sendsTracingToConfiguredAddress(org.apache.servicecomb.tests.tracing.ZipkinTracingIntegrationTest) > Time elapsed: 10.252 sec <<< FAILURE! > java.lang.AssertionError: > Expected: iterable over ["/hello", "public abstract java.lang.String > org.apache.servicecomb.tests.tracing.SlowRepo.crawl() throws > java.lang.InterruptedException", "/bonjour", "/pojo"] in any order > but: No item matches: "/hello", "/bonjour" in ["public abstract > java.lang.String org.apache.servicecomb.tests.tracing.SlowRepo.crawl() throws > java.lang.InterruptedException", "/pojo"] > at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20) > at > org.apache.servicecomb.tests.tracing.TracingTestBase.assertThatSpansReceivedByZipkin(TracingTestBase.java:91) > at > org.apache.servicecomb.tests.tracing.ZipkinTracingIntegrationTest.sendsTracingToConfiguredAddress(ZipkinTracingIntegrationTest.java:51) > 05:06:39,416 [//] INFO [Thread-4] support.AbstractApplicationContext > (AbstractApplicationContext.java:987) - Closing -- This message was sent by Atlassian JIRA (v7.6.3#76005)