Skip to content

Fix for Vert.x 4.0 instrumentation to close span on timeout #5772

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
ygree merged 2 commits into from
Aug 25, 2023
Merged

Fix for Vert.x 4.0 instrumentation to close span on timeout #5772

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
0e5a85d
Fix for Vert.x 4.0 instrumentation to close span on timeout
ygree Aug 23, 2023
b9895fb
Reuse netty41.AttributeKeys in Vert.x instrumentation to access the h…
ygree Aug 24, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
19 changes: 19 additions & 0 deletions ...n/java/datadog/trace/instrumentation/netty40/client/HttpClientResponseTracingHandler.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -64,4 +64,23 @@ public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) throws E
super.exceptionCaught(ctx, cause);
}
}

@Override
public void channelInactive(ChannelHandlerContext ctx) throws Exception {

@bantonsson bantonsson Aug 24, 2023

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I guess this is to ensure that the netty versions behave the same, since vertx seem to need netty 4.1.

@ygree ygree Aug 24, 2023

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Correct, Vert.x uses Netty 4.1. I added this for Netty 4.0 too just because there might be a similar to Vert.x case leading to an unfinished span. Making sure we finish it here will potentially prevent this type of an issue.

final Attribute<AgentSpan> parentAttr = ctx.channel().attr(CLIENT_PARENT_ATTRIBUTE_KEY);
parentAttr.setIfAbsent(noopSpan());
final AgentSpan parent = parentAttr.get();
final AgentSpan span = ctx.channel().attr(SPAN_ATTRIBUTE_KEY).getAndSet(parent);
if (span != null) {
try (final AgentScope scope = activateSpan(span)) {
DECORATE.beforeFinish(span);
span.finish();
}
}
// We want the callback in the scope of the parent, not the client span
try (final AgentScope scope = activateSpan(parent)) {
scope.setAsyncPropagation(true);
super.channelInactive(ctx);
}
}
}
19 changes: 19 additions & 0 deletions ...n/java/datadog/trace/instrumentation/netty41/client/HttpClientResponseTracingHandler.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -64,4 +64,23 @@ public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) throws E
super.exceptionCaught(ctx, cause);
}
}

@Override
public void channelInactive(ChannelHandlerContext ctx) throws Exception {
final Attribute<AgentSpan> parentAttr = ctx.channel().attr(CLIENT_PARENT_ATTRIBUTE_KEY);
parentAttr.setIfAbsent(noopSpan());
final AgentSpan parent = parentAttr.get();
final AgentSpan span = ctx.channel().attr(SPAN_ATTRIBUTE_KEY).getAndSet(parent);
if (span != null) {
try (final AgentScope scope = activateSpan(span)) {
DECORATE.beforeFinish(span);
span.finish();
}
}
// We want the callback in the scope of the parent, not the client span
try (final AgentScope scope = activateSpan(parent)) {
scope.setAsyncPropagation(true);
super.channelInactive(ctx);
}
}
}
2 changes: 2 additions & 0 deletions dd-java-agent/instrumentation/vertx-web-4.0/build.gradle
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,8 @@ artifacts {
}

dependencies {
api project(':dd-java-agent:instrumentation:netty-4.1-shared')

compileOnly group: 'io.vertx', name: 'vertx-web', version: '4.2.7'

testImplementation project(':dd-java-agent:instrumentation:netty-4.1')
Expand Down
67 changes: 67 additions & 0 deletions .../datadog/trace/instrumentation/vertx_4_0/client/HttpClientRequestBaseInstrumentation.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,67 @@
package datadog.trace.instrumentation.vertx_4_0.client;

import static datadog.trace.agent.tooling.bytebuddy.matcher.NameMatchers.named;
import static datadog.trace.bootstrap.instrumentation.api.AgentTracer.activateSpan;
import static datadog.trace.bootstrap.instrumentation.httpurlconnection.HttpUrlConnectionDecorator.DECORATE;
import static net.bytebuddy.matcher.ElementMatchers.isMethod;
import static net.bytebuddy.matcher.ElementMatchers.isPackagePrivate;
import static net.bytebuddy.matcher.ElementMatchers.takesArgument;

import com.google.auto.service.AutoService;
import datadog.trace.agent.tooling.Instrumenter;
import datadog.trace.bootstrap.instrumentation.api.AgentScope;
import datadog.trace.bootstrap.instrumentation.api.AgentSpan;
import datadog.trace.instrumentation.netty41.AttributeKeys;

@bantonsson bantonsson Aug 24, 2023

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does this need to be declared as a helper class here as well?

@ygree ygree Aug 24, 2023

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep, otherwise it'll fail at muzzle check

import io.vertx.core.http.impl.HttpClientStream;
import net.bytebuddy.asm.Advice;

@AutoService(Instrumenter.class)
public class HttpClientRequestBaseInstrumentation extends Instrumenter.Tracing
implements Instrumenter.ForKnownTypes {
static final String[] CONCRETE_TYPES = {
"io.vertx.core.http.impl.HttpClientRequestImpl",
"io.vertx.core.http.impl.HttpClientRequestPushPromise"
};

public HttpClientRequestBaseInstrumentation() {
super("vertx", "vertx-4.0");
}

@Override
public String[] helperClassNames() {
return new String[] {"datadog.trace.instrumentation.netty41.AttributeKeys"};
}

@Override
public void adviceTransformations(AdviceTransformation transformation) {
transformation.applyAdvice(
isMethod()
.and(isPackagePrivate())
.and(named("reset"))
.and(takesArgument(0, named("java.lang.Throwable"))),
HttpClientRequestBaseInstrumentation.class.getName() + "$ResetAdvice");
}

@Override
public String[] knownMatchingTypes() {
return CONCRETE_TYPES;
}

public static class ResetAdvice {
@Advice.OnMethodExit(suppress = Throwable.class)
public static void onExit(
@Advice.Argument(value = 0) Throwable cause,
@Advice.FieldValue("stream") final HttpClientStream stream,
@Advice.Return(readOnly = false) boolean result) {
if (result) {
AgentSpan nettySpan =
stream.connection().channel().attr(AttributeKeys.SPAN_ATTRIBUTE_KEY).get();
if (nettySpan != null) {
try (final AgentScope scope = activateSpan(nettySpan)) {
DECORATE.onError(scope, cause);
}
}
}
}
}
}
37 changes: 35 additions & 2 deletions ...ent/instrumentation/vertx-web-4.0/src/test/groovy/client/VertxHttpClientForkedTest.groovy
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,8 @@ import io.vertx.core.VertxOptions
import io.vertx.core.http.HttpClientOptions
import io.vertx.core.http.HttpClientResponse
import io.vertx.core.http.HttpMethod
import io.vertx.core.http.RequestOptions
import io.vertx.core.http.impl.NoStackTraceTimeoutException
import spock.lang.AutoCleanup
import spock.lang.Shared

Expand Down Expand Up @@ -37,9 +39,20 @@ class VertxHttpClientForkedTest extends HttpClientTest implements TestingNettyHt

@Override
int doRequest(String method, URI uri, Map<String, String> headers, String body, Closure callback) {
return doRequest(method, uri, headers, body, callback, -1)
}

int doRequest(String method, URI uri, Map<String, String> headers, String body, Closure callback, long timeout) {
CompletableFuture<HttpClientResponse> future = new CompletableFuture<>()

httpClient.request(HttpMethod.valueOf(method), uri.port, uri.host, "$uri", { requestReadyToBeSend ->
RequestOptions requestOptions = new RequestOptions()
.setMethod(HttpMethod.valueOf(method))
.setHost(uri.host)
.setPort(uri.port)
.setURI(uri.toString())
.setTimeout(timeout)

httpClient.request(requestOptions, { requestReadyToBeSend ->
def request = requestReadyToBeSend.result()
headers.each { request.putHeader(it.key, it.value) }
request.send(body, { response ->
Expand All @@ -52,7 +65,8 @@ class VertxHttpClientForkedTest extends HttpClientTest implements TestingNettyHt
})
})

return future.get(10, TimeUnit.SECONDS).statusCode()
HttpClientResponse response = future.get(10, TimeUnit.SECONDS)
return response == null ? 0 : response.statusCode()
}

@Override
Expand All @@ -74,4 +88,23 @@ class VertxHttpClientForkedTest extends HttpClientTest implements TestingNettyHt
// FIXME: figure out how to configure timeouts.
false
}

def "handle timeout"() {
when:
def status = doRequest(method, url, [:], "", null, timeout)

then:
status == 0
assertTraces(1) {
trace(size(1)) {
clientSpan(it, null, method, false, false, url, null, true, ex)
}
}

where:
timeout = 1000
method = "GET"
url = server.address.resolve("/timeout")
ex = new NoStackTraceTimeoutException("The timeout period of ${timeout}ms has been exceeded while executing GET http://localhost:${url.port}/timeout for server localhost:${url.port}")
}
}
4 changes: 4 additions & 0 deletions dd-java-agent/testing/src/main/groovy/datadog/trace/agent/test/base/HttpClientTest.groovy
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -87,6 +87,10 @@ abstract class HttpClientTest extends VersionedNamingTestBase {
.addHeader('x-datadog-test-response-header', 'baz')
.send(msg)
}
prefix("/timeout") {
Thread.sleep(10_000)

@bantonsson bantonsson Aug 24, 2023

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we have to wait for 10 seconds? Could we make the timeouts shorter in the tests?

@ygree ygree Aug 24, 2023

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No, we don't have to wait. The whole point for this endpoint is to prevent it responding. The client is supposed to cancel it earlier in this case it's 1s. Unless test is incorrect and the client doesn't cancel within shorter interval then it will wait for at max 10 seconds and then fail.

throw new IllegalStateException("Should never happen")
}
}
}

Expand Down