Make zipkin's current context can be nested #1262

kojilin · 2018-06-17T15:12:36Z

Apply this change will fix TraceContext leak in thread problem.
There is a case that we keep armeria's request context aware CompletableFuture
for fetching data, and let multiple request register callback on that future.
So there is a problem that future uses first request's eventloop and RequestContext
to call waiting handlers, but each handler may wrap with it's RequestContext, so
there is nested RequestContext on same thread(onEnter->onEnter->onExit->onExit).

Another solution is application developer should always jump back to current request's
context aware eventloop. e.g.


cachedFuture.acceptAsync((r, e)->{
  ...
}, RequestContext.current.contextAwareEventloop);

I'm not sure if armeria side need to take care of this or not...

Apply this change will fix TraceContext leak in thread problem. There is a case that we keep armeria's request context aware CompletableFuture for fetching data, and let multiple request register callback on that future. So there is a problem that future uses first request's eventloop and RequestContext to call waiting handlers, but each handler may wrap with it's RequestContext, so there is nested RequestContext on same thread(onEnter->onEnter->onExit->onExit). Another solution is application developer should always jump back to current request's context aware eventloop. e.g. ``` cachedFuture.acceptAsync((r, e)->{ ... }, RequestContext.current.contextAwareEventloop); ``` I'm not sure if armeria side need to take care of this or not...

codecov · 2018-06-17T16:20:06Z

Codecov Report

Merging #1262 into master will decrease coverage by 0.06%.
The diff coverage is 100%.

@@            Coverage Diff             @@
##           master    #1262      +/-   ##
==========================================
- Coverage   72.64%   72.57%   -0.07%     
==========================================
  Files         557      558       +1     
  Lines       24141    24156      +15     
  Branches     2943     2944       +1     
==========================================
- Hits        17538    17532       -6     
- Misses       5055     5073      +18     
- Partials     1548     1551       +3

Impacted Files	Coverage Δ
...orp/armeria/server/tracing/HttpTracingService.java	`100% <100%> (ø)`	⬆️
...corp/armeria/client/tracing/HttpTracingClient.java	`84.21% <100%> (ø)`	⬆️
...corp/armeria/internal/tracing/SpanContextUtil.java	`100% <100%> (ø)`	⬆️
...p/armeria/internal/tracing/SpanInScopeWrapper.java	`100% <100%> (ø)`
...n/java/com/linecorp/armeria/server/HttpServer.java	`40% <0%> (-10%)`	⬇️
...com/linecorp/armeria/server/HttpServerHandler.java	`73.98% <0%> (-3.38%)`	⬇️
...a/com/linecorp/armeria/common/util/Exceptions.java	`29.16% <0%> (-2.09%)`	⬇️
...corp/armeria/common/stream/FixedStreamMessage.java	`91.07% <0%> (-1.79%)`	⬇️
...inecorp/armeria/client/grpc/ArmeriaClientCall.java	`77.77% <0%> (-1.71%)`	⬇️
.../linecorp/armeria/internal/Http1ObjectEncoder.java	`73.13% <0%> (-1.5%)`	⬇️
... and 5 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 201af60...b61e37a. Read the comment docs.

trustin

Just some nits.

trustin · 2018-06-18T02:13:11Z

zipkin/src/main/java/com/linecorp/armeria/internal/tracing/SpanInScopeWrapper.java

+    }
+
+    @Nullable
+    public SpanInScopeWrapper getPrevious() {


nit: previous()?

trustin · 2018-06-18T02:13:58Z

zipkin/src/main/java/com/linecorp/armeria/internal/tracing/SpanInScopeWrapper.java

+import brave.Tracer.SpanInScope;
+
+/**
+ * SpanInScope Wrapper for keeping previous span scope.


{@link SpanInScope} wrapper that keeps the previous {@link SpanInScope}.

anuraaga · 2018-06-18T02:22:40Z

Can you add test cases with the offending behavior? It'd also help document the affected case.

anuraaga · 2018-06-18T03:08:08Z

I'm also sort of wondering what it means in terms of tracing to restore a parent context after a child context.

Assuming server_span, client_span_1, and client_span_2, I think we end up with something like

<------------------server_span----------------------->
        <--------client_span_1------------------>
                             <--server_span?----->
                               <--client_span_2-->

client_span_2's parent will be server_span, but I think it's supposed to be client_span_1. Maybe this is correct, but conceptually I'm having trouble grokking it - what do you think about this? Personally I always run my callbacks on the request thread explicitly because I'd expect tracing to break in any other threading model. Though with a code example, maybe I'll realize I'm thinking of a different case :)

/cc @adriancole if you have any thoughts.

kojilin · 2018-06-18T03:55:45Z

Add test. So if we don't keep previous scope and restore, then there is a scope can't be close.

Not sure the question, but I don't think there is a situation that client scope has another client scope ?

kojilin · 2018-06-18T03:58:18Z

...n/src/test/java/com/linecorp/armeria/it/tracing/HttpTracingNestedContextIntegrationTest.java

+        protected void configure(ServerBuilder sb) throws Exception {
+
+            final CountDownLatch countDownLatch = new CountDownLatch(2);
+            final AtomicReference<CompletableFuture<HttpStatus>> cache = new AtomicReference<>();


We use caffeine, so this is similar situation.

kojilin · 2018-06-18T03:59:01Z

...n/src/test/java/com/linecorp/armeria/it/tracing/HttpTracingNestedContextIntegrationTest.java

+                    try {
+                        final RequestContext requestContext = RequestContext.current();
+                        return HttpResponse.from(
+                                cache.get().thenApply(status -> {


Or the application dev must always know using thenApplyAsync with current evetloop.

anuraaga · 2018-06-18T04:09:02Z

...n/src/test/java/com/linecorp/armeria/it/tracing/HttpTracingNestedContextIntegrationTest.java

+                        final RequestContext requestContext = RequestContext.current();
+                        return HttpResponse.from(
+                                cache.get().thenApply(status -> {
+                                    try (SafeCloseable ignored = RequestContext.push(requestContext)) {


I see, the example seems to have two unrelated server context's on the same request context stack. Is this allowed by the semantics of RequestContext? We have features like RequestContext.onChild, which I don't think support this sort of behavior, pushing a context here is like saying we're creating a new child context, so the unrelated "parent"'s onChildCallbacks would run too from what I can tell.

oops, right. Didn't notice about #onChild.
Also do you think I should use propagateContextIfNotPresent in here too? https://github.com/line/armeria/blob/master/rxjava/src/main/java/com/linecorp/armeria/common/rxjava/RequestContextCompletable.java#L38

Yeah going with propagate if not present seems safer for that sort of callback, so while new contexts don't get set up properly, at least old contexts won't be affected poorly which I guess is usually better. Maybe some sort of logging could be added for such a case.

FWIW, the reason I added this comment a long time ago is because in my experience it's extremely difficult if not impossible to get "context" to work in asynchronous code in Java (which can only try mapping them to ThreadLocal) without jumping threads. Perhaps we could call this out in the documentation better - wonder what others' thoughts are

https://github.com/line/armeria/blob/master/core/src/main/java/com/linecorp/armeria/common/RequestContext.java#L271

Thanks, it's so easy to forget using Async callback so thats why we want to use this kind of hook for chaining sync/async operations.

I will close this PR and try to make RxJava hook strictly.

kojilin requested review from hyangtack, minwoox and trustin as code owners June 17, 2018 15:12

kojilin requested a review from anuraaga June 17, 2018 15:12

kojilin force-pushed the zipkin-fix branch from e27a778 to a26697c Compare June 17, 2018 15:49

trustin added the defect label Jun 18, 2018

trustin added this to the 0.67.0 milestone Jun 18, 2018

trustin approved these changes Jun 18, 2018

View reviewed changes

minwoox approved these changes Jun 18, 2018

View reviewed changes

hyangtack approved these changes Jun 18, 2018

View reviewed changes

kojilin commented Jun 18, 2018

View reviewed changes

Append test.

b61e37a

kojilin force-pushed the zipkin-fix branch from f0579f4 to b61e37a Compare June 18, 2018 04:00

anuraaga reviewed Jun 18, 2018

View reviewed changes

kojilin closed this Jun 18, 2018

kojilin deleted the zipkin-fix branch June 18, 2018 05:03

trustin removed this from the 0.67.0 milestone Jun 18, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make zipkin's current context can be nested #1262

Make zipkin's current context can be nested #1262

kojilin commented Jun 17, 2018

codecov bot commented Jun 17, 2018 •

edited

Loading

trustin left a comment

trustin Jun 18, 2018

trustin Jun 18, 2018

anuraaga commented Jun 18, 2018

anuraaga commented Jun 18, 2018 •

edited

Loading

kojilin commented Jun 18, 2018

kojilin Jun 18, 2018

kojilin Jun 18, 2018

anuraaga Jun 18, 2018 •

edited

Loading

kojilin Jun 18, 2018 •

edited

Loading

anuraaga Jun 18, 2018 •

edited

Loading

kojilin Jun 18, 2018

Make zipkin's current context can be nested #1262

Make zipkin's current context can be nested #1262

Conversation

kojilin commented Jun 17, 2018

codecov bot commented Jun 17, 2018 • edited Loading

Codecov Report

trustin left a comment

Choose a reason for hiding this comment

trustin Jun 18, 2018

Choose a reason for hiding this comment

trustin Jun 18, 2018

Choose a reason for hiding this comment

anuraaga commented Jun 18, 2018

anuraaga commented Jun 18, 2018 • edited Loading

kojilin commented Jun 18, 2018

kojilin Jun 18, 2018

Choose a reason for hiding this comment

kojilin Jun 18, 2018

Choose a reason for hiding this comment

anuraaga Jun 18, 2018 • edited Loading

Choose a reason for hiding this comment

kojilin Jun 18, 2018 • edited Loading

Choose a reason for hiding this comment

anuraaga Jun 18, 2018 • edited Loading

Choose a reason for hiding this comment

kojilin Jun 18, 2018

Choose a reason for hiding this comment

codecov bot commented Jun 17, 2018 •

edited

Loading

anuraaga commented Jun 18, 2018 •

edited

Loading

anuraaga Jun 18, 2018 •

edited

Loading

kojilin Jun 18, 2018 •

edited

Loading

anuraaga Jun 18, 2018 •

edited

Loading