You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@servicecomb.apache.org by "Yang Bo (JIRA)" <ji...@apache.org> on 2018/01/26 09:22:00 UTC
[jira] [Commented] (SCB-293) trace integration test has small
probability lost data.
[ 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)