[
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)
