Skip to content

Commit

Permalink
Fix prematurely ending server span on undertow (#2560)
Browse files Browse the repository at this point in the history
* Fix permaturely ending server span on undertow

* Trigger Build

* Add undertow to supported frameworks

* Review fixes

* Update instrumentation/undertow/javaagent/src/test/groovy/UndertowServerTest.groovy

Co-authored-by: Trask Stalnaker <[email protected]>

* Update instrumentation/undertow/javaagent/src/test/groovy/UndertowServerTest.groovy

Co-authored-by: Trask Stalnaker <[email protected]>

* Review fixes

Co-authored-by: Trask Stalnaker <[email protected]>
  • Loading branch information
laurit and trask authored Mar 12, 2021
1 parent 182574a commit ff3542e
Show file tree
Hide file tree
Showing 10 changed files with 285 additions and 87 deletions.
1 change: 1 addition & 0 deletions docs/supported-libraries.md
Original file line number Diff line number Diff line change
Expand Up @@ -84,6 +84,7 @@ These are the supported libraries and frameworks:
| [Spymemcached](https://github.com/couchbase/spymemcached) | 2.12+ |
| [Struts2](https://github.com/apache/struts) | 2.3+ |
| [Twilio](https://github.com/twilio/twilio-java) | 6.6+ (not including 8.x yet) |
| [Undertow](https://undertow.io/) | 1.4+ |
| [Vert.x](https://vertx.io) | 3.0+ |
| [Vert.x RxJava2](https://vertx.io/docs/vertx-rx/java2/) | 3.5+ |

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,6 @@
import static io.opentelemetry.javaagent.instrumentation.undertow.UndertowHttpServerTracer.tracer;

import io.opentelemetry.context.Context;
import io.undertow.server.DefaultResponseListener;
import io.undertow.server.ExchangeCompletionListener;
import io.undertow.server.HttpServerExchange;

Expand All @@ -21,12 +20,7 @@ public EndSpanListener(Context context) {

@Override
public void exchangeEvent(HttpServerExchange exchange, NextListener nextListener) {
Throwable throwable = exchange.getAttachment(DefaultResponseListener.EXCEPTION);
if (throwable != null) {
tracer().endExceptionally(context, throwable, exchange);
} else {
tracer().end(context, exchange);
}
tracer().exchangeCompleted(context, exchange);
nextListener.proceed();
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -11,9 +11,10 @@
import io.opentelemetry.instrumentation.api.servlet.ServletSpanNaming;
import io.opentelemetry.instrumentation.api.tracer.HttpServerTracer;
import io.opentelemetry.javaagent.instrumentation.api.undertow.KeyHolder;
import io.opentelemetry.javaagent.instrumentation.api.undertow.UndertowActiveHandlers;
import io.undertow.server.DefaultResponseListener;
import io.undertow.server.HttpServerExchange;
import io.undertow.util.AttachmentKey;
import java.lang.reflect.Method;
import java.net.InetSocketAddress;
import org.checkerframework.checker.nullness.qual.Nullable;

Expand All @@ -31,17 +32,53 @@ protected String getInstrumentationName() {
return "io.opentelemetry.javaagent.undertow";
}

public Context startServerSpan(HttpServerExchange exchange, Method instrumentedMethod) {
public Context startServerSpan(HttpServerExchange exchange) {
return startSpan(
exchange, exchange, exchange, "HTTP " + exchange.getRequestMethod().toString());
}

@Override
protected Context customizeContext(Context context, HttpServerExchange exchange) {
context = ServletSpanNaming.init(context);
// span is ended when counter reaches 0, we start from 2 which accounts for the
// handler that started the span and exchange completion listener
context = UndertowActiveHandlers.init(context, 2);
return AppServerBridge.init(context);
}

public void handlerStarted(Context context) {
// request was dispatched to a new thread, handler on the original thread
// may exit before this one so we need to wait for this handler to complete
// before ending span
UndertowActiveHandlers.increment(context);
}

public void handlerCompleted(Context context, Throwable throwable, HttpServerExchange exchange) {
// end the span when this is the last handler to complete and exchange has
// been completed
if (UndertowActiveHandlers.decrementAndGet(context) == 0) {
endSpan(context, throwable, exchange);
}
}

public void exchangeCompleted(Context context, HttpServerExchange exchange) {
// after exchange is completed we can read response status
// if all handlers have completed we can end the span, if there are running
// handlers we'll end the span when last handler exits
if (UndertowActiveHandlers.decrementAndGet(context) == 0) {
Throwable throwable = exchange.getAttachment(DefaultResponseListener.EXCEPTION);
endSpan(context, throwable, exchange);
}
}

private void endSpan(Context context, Throwable throwable, HttpServerExchange exchange) {
if (throwable != null) {
tracer().endExceptionally(context, throwable, exchange);
} else {
tracer().end(context, exchange);
}
}

@SuppressWarnings("unchecked")
@Override
public @Nullable Context getServerContext(HttpServerExchange exchange) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -21,7 +21,6 @@
import io.opentelemetry.javaagent.tooling.InstrumentationModule;
import io.opentelemetry.javaagent.tooling.TypeInstrumentation;
import io.undertow.server.HttpServerExchange;
import java.lang.reflect.Method;
import java.util.List;
import java.util.Map;
import net.bytebuddy.asm.Advice;
Expand All @@ -33,7 +32,7 @@
public class UndertowInstrumentationModule extends InstrumentationModule {

public UndertowInstrumentationModule() {
super("undertow", "undertow-2.0");
super("undertow", "undertow-1.4");
}

@Override
Expand Down Expand Up @@ -65,33 +64,38 @@ public Map<? extends ElementMatcher<? super MethodDescription>, String> transfor
public static class UndertowHandlerAdvice {
@Advice.OnMethodEnter(suppress = Throwable.class)
public static void onEnter(
@Advice.Origin Method method,
@Advice.Argument(value = 0, readOnly = false) HttpServerExchange exchange,
@Advice.Local("otelContext") Context context,
@Advice.Local("otelScope") Scope scope) {
Context attachedContext = tracer().getServerContext(exchange);
if (attachedContext != null) {
if (!Java8BytecodeBridge.currentContext().equals(attachedContext)) {
// request processing is dispatched to another thread
scope = attachedContext.makeCurrent();
context = attachedContext;
tracer().handlerStarted(attachedContext);
}
return;
}

Context context = tracer().startServerSpan(exchange, method);
context = tracer().startServerSpan(exchange);
scope = context.makeCurrent();

exchange.addExchangeCompleteListener(new EndSpanListener(context));
}

@Advice.OnMethodExit(onThrowable = Throwable.class, suppress = Throwable.class)
public static void onExit(
@Advice.Argument(value = 0, readOnly = false) HttpServerExchange exchange,
@Advice.Argument(0) HttpServerExchange exchange,
@Advice.Thrown Throwable throwable,
@Advice.Local("otelContext") Context context,
@Advice.Local("otelScope") Scope scope) {
if (scope == null) {
return;
}

scope.close();
// span is closed by EndSpanListener

tracer().handlerCompleted(context, throwable, exchange);
}
}
}
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,182 @@
/*
* Copyright The OpenTelemetry Authors
* SPDX-License-Identifier: Apache-2.0
*/

import static io.opentelemetry.instrumentation.test.base.HttpServerTest.ServerEndpoint.ERROR
import static io.opentelemetry.instrumentation.test.base.HttpServerTest.ServerEndpoint.EXCEPTION
import static io.opentelemetry.instrumentation.test.base.HttpServerTest.ServerEndpoint.QUERY_PARAM
import static io.opentelemetry.instrumentation.test.base.HttpServerTest.ServerEndpoint.REDIRECT
import static io.opentelemetry.instrumentation.test.base.HttpServerTest.ServerEndpoint.SUCCESS
import static io.opentelemetry.instrumentation.test.utils.TraceUtils.basicSpan
import static io.opentelemetry.instrumentation.test.utils.TraceUtils.runUnderTrace

import io.opentelemetry.api.trace.Span
import io.opentelemetry.api.trace.SpanKind
import io.opentelemetry.instrumentation.test.AgentTestTrait
import io.opentelemetry.instrumentation.test.base.HttpServerTest
import io.opentelemetry.semconv.trace.attributes.SemanticAttributes
import io.undertow.Handlers
import io.undertow.Undertow
import io.undertow.util.Headers
import io.undertow.util.StatusCodes
import okhttp3.HttpUrl
import okhttp3.Response

//TODO make test which mixes handlers and servlets
class UndertowServerTest extends HttpServerTest<Undertow> implements AgentTestTrait {

@Override
Undertow startServer(int port) {
Undertow server = Undertow.builder()
.addHttpListener(port, "localhost")
.setHandler(Handlers.path()
.addExactPath(SUCCESS.rawPath()) { exchange ->
controller(SUCCESS) {
exchange.getResponseSender().send(SUCCESS.body)
}
}
.addExactPath(QUERY_PARAM.rawPath()) { exchange ->
controller(QUERY_PARAM) {
exchange.getResponseSender().send(exchange.getQueryString())
}
}
.addExactPath(REDIRECT.rawPath()) { exchange ->
controller(REDIRECT) {
exchange.setStatusCode(StatusCodes.FOUND)
exchange.getResponseHeaders().put(Headers.LOCATION, REDIRECT.body)
exchange.endExchange()
}
}
.addExactPath(ERROR.rawPath()) { exchange ->
controller(ERROR) {
exchange.setStatusCode(ERROR.status)
exchange.getResponseSender().send(ERROR.body)
}
}
.addExactPath(EXCEPTION.rawPath()) { exchange ->
controller(EXCEPTION) {
throw new Exception(EXCEPTION.body)
}
}
.addExactPath("sendResponse") { exchange ->
Span.current().addEvent("before-event")
runUnderTrace("sendResponse") {
exchange.setStatusCode(StatusCodes.OK)
exchange.getResponseSender().send("sendResponse")
}
// event is added only when server span has not been ended
// we need to make sure that sending response does not end server span
Span.current().addEvent("after-event")
}
.addExactPath("sendResponseWithException") { exchange ->
Span.current().addEvent("before-event")
runUnderTrace("sendResponseWithException") {
exchange.setStatusCode(StatusCodes.OK)
exchange.getResponseSender().send("sendResponseWithException")
}
// event is added only when server span has not been ended
// we need to make sure that sending response does not end server span
Span.current().addEvent("after-event")
throw new Exception("exception after sending response")
}
).build()
server.start()
return server
}

@Override
void stopServer(Undertow undertow) {
undertow.stop()
}

@Override
String expectedServerSpanName(ServerEndpoint endpoint) {
return "HTTP GET"
}

def "test send response"() {
setup:
def uri = address.resolve("sendResponse")
def url = HttpUrl.get(uri).newBuilder().build()
def request = request(url, "GET", null).build()
Response response = client.newCall(request).execute()

expect:
response.code() == 200
response.body().string().trim() == "sendResponse"

and:
assertTraces(1) {
trace(0, 2) {
it.span(0) {
hasNoParent()
name "HTTP GET"
kind SpanKind.SERVER

event(0) {
eventName "before-event"
}
event(1) {
eventName "after-event"
}

attributes {
"${SemanticAttributes.NET_PEER_PORT.key}" { it instanceof Long }
"${SemanticAttributes.NET_PEER_IP.key}" "127.0.0.1"
"${SemanticAttributes.HTTP_CLIENT_IP.key}" TEST_CLIENT_IP
"${SemanticAttributes.HTTP_URL.key}" uri.toString()
"${SemanticAttributes.HTTP_METHOD.key}" "GET"
"${SemanticAttributes.HTTP_STATUS_CODE.key}" 200
"${SemanticAttributes.HTTP_FLAVOR.key}" "1.1"
"${SemanticAttributes.HTTP_USER_AGENT.key}" TEST_USER_AGENT
}
}
basicSpan(it, 1, "sendResponse", span(0))
}
}
}

def "test send response with exception"() {
setup:
def uri = address.resolve("sendResponseWithException")
def url = HttpUrl.get(uri).newBuilder().build()
def request = request(url, "GET", null).build()
Response response = client.newCall(request).execute()

expect:
response.code() == 200
response.body().string().trim() == "sendResponseWithException"

and:
assertTraces(1) {
trace(0, 2) {
it.span(0) {
hasNoParent()
name "HTTP GET"
kind SpanKind.SERVER

event(0) {
eventName "before-event"
}
event(1) {
eventName "after-event"
}
errorEvent(Exception, "exception after sending response", 2)

attributes {
"${SemanticAttributes.NET_PEER_PORT.key}" { it instanceof Long }
"${SemanticAttributes.NET_PEER_IP.key}" "127.0.0.1"
"${SemanticAttributes.HTTP_CLIENT_IP.key}" TEST_CLIENT_IP
"${SemanticAttributes.HTTP_URL.key}" uri.toString()
"${SemanticAttributes.HTTP_METHOD.key}" "GET"
"${SemanticAttributes.HTTP_STATUS_CODE.key}" 200
"${SemanticAttributes.HTTP_FLAVOR.key}" "1.1"
"${SemanticAttributes.HTTP_USER_AGENT.key}" TEST_USER_AGENT
}
}
basicSpan(it, 1, "sendResponseWithException", span(0))
}
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,8 @@ muzzle {
pass {
group = "io.undertow"
module = 'undertow-core'
versions = "[2.0.0.Final,)"
versions = "[1.4.0.Final,)"
assertInverse = true
}
}

Expand Down
Loading

0 comments on commit ff3542e

Please sign in to comment.