debugging

Author: jaydeluca

instrumentation/spring/spring-webflux/spring-webflux-5.0/javaagent/src/main/java/io/opentelemetry/javaagent/instrumentation/spring/webflux/v5_0/server/HandlerAdapterInstrumentation.java

@@ -47,6 +47,10 @@ public ElementMatcher<TypeDescription> typeMatcher() {
 
   @Override
   public void transform(TypeTransformer transformer) {
+    // Get the class name being transformed - this requires accessing transformer internals
+    // For now, just log that we're transforming
+    System.out.println("=== HandlerAdapterInstrumentation.transform() called ===");
+    System.out.println("  Applying advice to 'handle' method");
     transformer.applyAdviceToMethod(
         isMethod()
             .and(isPublic())
@@ -55,6 +59,7 @@ public void transform(TypeTransformer transformer) {
             .and(takesArgument(1, Object.class))
             .and(takesArguments(2)),
         this.getClass().getName() + "$HandleAdvice");
+    System.out.println("=== HandlerAdapterInstrumentation advice applied ===");
   }
 
   @SuppressWarnings("unused")
@@ -71,7 +76,13 @@ private AdviceScope(Context context, Scope scope) {
 
       @Nullable
       public static AdviceScope enter(ServerWebExchange exchange, Object handler) {
+        System.out.println("=== HandlerAdapter.enter() called ===");
+        System.out.println(
+            "  Handler: " + (handler != null ? handler.getClass().getName() : "null"));
+        System.out.println("  Thread: " + Thread.currentThread().getName());
+
         Context parentContext = Context.current();
+        System.out.println("  Parent context: " + parentContext);
 
         // HttpRouteSource.CONTROLLER has useFirst true, and it will update http.route only once
         // using the last portion of the nested path.
@@ -82,13 +93,20 @@ public static AdviceScope enter(ServerWebExchange exchange, Object handler) {
             parentContext, HttpServerRouteSource.NESTED_CONTROLLER, httpRouteGetter(), exchange);
 
         if (handler == null) {
+          System.out.println("  Handler is null, returning null");
           return null;
         }
 
-        if (!instrumenter().shouldStart(parentContext, handler)) {
+        boolean shouldStart = instrumenter().shouldStart(parentContext, handler);
+        System.out.println("  shouldStart: " + shouldStart);
+
+        if (!shouldStart) {
+          System.out.println("  instrumenter().shouldStart returned false, returning null");
           return null;
         }
+
         Context context = instrumenter().start(parentContext, handler);
+        System.out.println("  Started new context: " + context);
         return new AdviceScope(context, context.makeCurrent());
       }
 
@@ -114,10 +132,13 @@ public Mono<HandlerResult> exit(
     }
 
     @Nullable
-    @Advice.OnMethodEnter(suppress = Throwable.class)
+    @Advice.OnMethodEnter
     public static AdviceScope methodEnter(
         @Advice.Argument(0) ServerWebExchange exchange, @Advice.Argument(1) Object handler) {
-      return AdviceScope.enter(exchange, handler);
+      System.out.println("=== HandlerAdapter.methodEnter() CALLED ===");
+      AdviceScope scope = AdviceScope.enter(exchange, handler);
+      System.out.println("  Returning AdviceScope: " + scope);
+      return scope;
     }
 
     @AssignReturned.ToReturned
@@ -129,11 +150,18 @@ public static Mono<HandlerResult> methodExit(
         @Advice.Thrown Throwable throwable,
         @Advice.Enter @Nullable AdviceScope adviceScope) {
 
+      System.out.println("=== HandlerAdapter.methodExit() CALLED ===");
+      System.out.println("  AdviceScope: " + adviceScope);
+      System.out.println("  Throwable: " + throwable);
+
       if (adviceScope == null) {
+        System.out.println("  AdviceScope is null, returning original mono");
         return mono;
       }
 
-      return adviceScope.exit(throwable, exchange, handler, mono);
+      Mono<HandlerResult> result = adviceScope.exit(throwable, exchange, handler, mono);
+      System.out.println("  Returning wrapped mono");
+      return result;
     }
   }
 }

instrumentation/spring/spring-webflux/spring-webflux-5.0/testing-webflux7/build.gradle.kts

@@ -12,6 +12,7 @@ dependencies {
   testInstrumentation(project(":instrumentation:reactor:reactor-netty:reactor-netty-1.0:javaagent"))
 
   testImplementation(project(":instrumentation:spring:spring-webflux:spring-webflux-5.0:testing"))
+  testImplementation(project(":instrumentation:spring:spring-webflux:spring-webflux-5.3:testing"))
 
   testImplementation("org.springframework.boot:spring-boot-starter-webflux:4.0.0")
   testImplementation("org.springframework.boot:spring-boot-starter-test:4.0.0")

instrumentation/spring/spring-webflux/spring-webflux-5.0/testing-webflux7/src/test/java/io/opentelemetry/javaagent/instrumentation/spring/webflux/v7_0/SpringThreadedSpringWebfluxTest.java

@@ -0,0 +1,38 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.spring.webflux.v7_0;
+
+import org.springframework.boot.reactor.netty.NettyReactiveWebServerFactory;
+import org.springframework.boot.test.context.SpringBootTest;
+import org.springframework.boot.test.context.TestConfiguration;
+import org.springframework.context.annotation.Bean;
+import reactor.netty.resources.LoopResources;
+import server.SpringWebFluxTestApplication;
+
+/**
+ * Run all Webflux tests under netty event loop having only 1 thread. Some of the bugs are better
+ * visible in this setup because same thread is reused for different requests.
+ */
+@SpringBootTest(
+    webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT,
+    classes = {
+      SpringWebFluxTestApplication.class,
+      SpringThreadedSpringWebfluxTest.ForceSingleThreadedNettyAutoConfiguration.class
+    })
+class SpringThreadedSpringWebfluxTest extends SpringWebfluxTest {
+
+  @TestConfiguration
+  static class ForceSingleThreadedNettyAutoConfiguration {
+    @Bean
+    NettyReactiveWebServerFactory nettyFactory() {
+      NettyReactiveWebServerFactory factory = new NettyReactiveWebServerFactory();
+      // Configure single-threaded event loop for Spring Boot 4
+      factory.addServerCustomizers(
+          server -> server.runOn(LoopResources.create("my-http", 1, true)));
+      return factory;
+    }
+  }
+}

instrumentation/spring/spring-webflux/spring-webflux-5.0/testing-webflux7/src/test/java/io/opentelemetry/javaagent/instrumentation/spring/webflux/v7_0/client/SpringWebfluxClientInstrumentationTest.java

@@ -0,0 +1,36 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.spring.webflux.v7_0.client;
+
+import io.opentelemetry.instrumentation.spring.webflux.client.AbstractSpringWebfluxClientInstrumentationTest;
+import io.opentelemetry.instrumentation.testing.junit.InstrumentationExtension;
+import io.opentelemetry.instrumentation.testing.junit.http.HttpClientInstrumentationExtension;
+import io.opentelemetry.instrumentation.testing.junit.http.HttpClientTestOptions;
+import org.junit.jupiter.api.condition.OS;
+import org.junit.jupiter.api.extension.RegisterExtension;
+import org.springframework.web.reactive.function.client.WebClient;
+
+class SpringWebfluxClientInstrumentationTest
+    extends AbstractSpringWebfluxClientInstrumentationTest {
+
+  @RegisterExtension
+  static final InstrumentationExtension testing = HttpClientInstrumentationExtension.forAgent();
+
+  @Override
+  protected WebClient.Builder instrument(WebClient.Builder builder) {
+    return builder;
+  }
+
+  @Override
+  protected void configure(HttpClientTestOptions.Builder optionsBuilder) {
+    super.configure(optionsBuilder);
+
+    // Disable remote connection tests on Windows due to reactor-netty creating extra spans
+    if (OS.WINDOWS.isCurrentOs()) {
+      optionsBuilder.setTestRemoteConnection(false);
+    }
+  }
+}

instrumentation/spring/spring-webflux/spring-webflux-5.0/testing-webflux7/src/test/java/io/opentelemetry/javaagent/instrumentation/spring/webflux/v7_0/server/base/ControllerSpringWebFluxServerTest.java

@@ -0,0 +1,78 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.spring.webflux.v7_0.server.base;
+
+import static io.opentelemetry.instrumentation.testing.junit.http.ServerEndpoint.EXCEPTION;
+import static io.opentelemetry.instrumentation.testing.junit.http.ServerEndpoint.NOT_FOUND;
+import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.equalTo;
+import static io.opentelemetry.sdk.testing.assertj.OpenTelemetryAssertions.satisfies;
+import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_MESSAGE;
+import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_STACKTRACE;
+import static io.opentelemetry.semconv.ExceptionAttributes.EXCEPTION_TYPE;
+
+import io.opentelemetry.api.trace.SpanKind;
+import io.opentelemetry.instrumentation.testing.junit.http.HttpServerTestOptions;
+import io.opentelemetry.instrumentation.testing.junit.http.ServerEndpoint;
+import io.opentelemetry.sdk.testing.assertj.SpanDataAssert;
+import io.opentelemetry.sdk.trace.data.StatusData;
+import java.util.Locale;
+
+public abstract class ControllerSpringWebFluxServerTest extends SpringWebFluxServerTest {
+
+  @Override
+  protected SpanDataAssert assertHandlerSpan(
+      SpanDataAssert span, String method, ServerEndpoint endpoint) {
+    String handlerSpanName =
+        ServerTestController.class.getSimpleName() + "." + endpoint.name().toLowerCase(Locale.ROOT);
+    if (endpoint == NOT_FOUND) {
+      handlerSpanName = "ResourceWebHandler.handle";
+    }
+    span.hasName(handlerSpanName).hasKind(SpanKind.INTERNAL);
+    if (endpoint == EXCEPTION) {
+      span.hasStatus(StatusData.error());
+      span.hasEventsSatisfyingExactly(
+          event ->
+              event
+                  .hasName("exception")
+                  .hasAttributesSatisfyingExactly(
+                      equalTo(EXCEPTION_TYPE, "java.lang.IllegalStateException"),
+                      equalTo(EXCEPTION_MESSAGE, EXCEPTION.getBody()),
+                      satisfies(EXCEPTION_STACKTRACE, val -> val.isInstanceOf(String.class))));
+    } else if (endpoint == NOT_FOUND) {
+      span.hasStatus(StatusData.error());
+      // Spring 7 uses NoResourceFoundException instead of ResponseStatusException
+      span.hasEventsSatisfyingExactly(
+          event ->
+              event
+                  .hasName("exception")
+                  .hasAttributesSatisfyingExactly(
+                      equalTo(
+                          EXCEPTION_TYPE,
+                          "org.springframework.web.reactive.resource.NoResourceFoundException"),
+                      satisfies(
+                          EXCEPTION_MESSAGE,
+                          val -> val.startsWith("404 NOT_FOUND \"No static resource notFound")),
+                      satisfies(EXCEPTION_STACKTRACE, val -> val.isInstanceOf(String.class))));
+    }
+    return span;
+  }
+
+  @Override
+  protected void configure(HttpServerTestOptions options) {
+    super.configure(options);
+    // TODO (trask) it seems like in this case ideally the controller span (which ends when the
+    // Mono that the controller returns completes) should end before the server span (which needs
+    // the result of the Mono)
+    options.setVerifyServerSpanEndTime(false);
+
+    options.setResponseCodeOnNonStandardHttpMethod(405);
+
+    // TODO fails on java 21
+    // span name set to "HTTP
+    // org.springframework.web.reactive.function.server.RequestPredicates$$Lambda/0x00007fa574969238@4aaf6fa2"
+    options.disableTestNonStandardHttpMethod();
+  }
+}

instrumentation/spring/spring-webflux/spring-webflux-5.0/testing-webflux7/src/test/java/io/opentelemetry/javaagent/instrumentation/spring/webflux/v7_0/server/base/DelayedControllerSpringWebFluxServerTest.java

@@ -0,0 +1,52 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.spring.webflux.v7_0.server.base;
+
+import io.opentelemetry.instrumentation.testing.junit.http.ServerEndpoint;
+import java.time.Duration;
+import java.util.function.Supplier;
+import org.springframework.boot.autoconfigure.EnableAutoConfiguration;
+import org.springframework.boot.reactor.netty.NettyReactiveWebServerFactory;
+import org.springframework.context.annotation.Bean;
+import org.springframework.context.annotation.Configuration;
+import org.springframework.web.bind.annotation.RestController;
+import reactor.core.publisher.Mono;
+
+/**
+ * Tests the case which uses annotated controller methods, and where "controller" span is created
+ * within a Mono map step, which follows a delay step. For exception endpoint, the exception is
+ * thrown within the last map step.
+ */
+class DelayedControllerSpringWebFluxServerTest extends ControllerSpringWebFluxServerTest {
+  @Override
+  protected Class<?> getApplicationClass() {
+    return Application.class;
+  }
+
+  @Configuration
+  @EnableAutoConfiguration
+  static class Application {
+    @Bean
+    Controller controller() {
+      return new Controller();
+    }
+
+    @Bean
+    NettyReactiveWebServerFactory nettyFactory() {
+      return new NettyReactiveWebServerFactory();
+    }
+  }
+
+  @RestController
+  static class Controller extends ServerTestController {
+    @Override
+    protected <T> Mono<T> wrapControllerMethod(ServerEndpoint endpoint, Supplier<T> handler) {
+      return Mono.just("")
+          .delayElement(Duration.ofMillis(10))
+          .map(unused -> controller(endpoint, handler));
+    }
+  }
+}

instrumentation/spring/spring-webflux/spring-webflux-5.0/testing-webflux7/src/test/java/io/opentelemetry/javaagent/instrumentation/spring/webflux/v7_0/server/base/DelayedHandlerSpringWebFluxServerTest.java

@@ -0,0 +1,60 @@
+/*
+ * Copyright The OpenTelemetry Authors
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+package io.opentelemetry.javaagent.instrumentation.spring.webflux.v7_0.server.base;
+
+import io.opentelemetry.instrumentation.testing.junit.http.ServerEndpoint;
+import java.time.Duration;
+import org.springframework.boot.autoconfigure.EnableAutoConfiguration;
+import org.springframework.boot.reactor.netty.NettyReactiveWebServerFactory;
+import org.springframework.context.annotation.Bean;
+import org.springframework.context.annotation.Configuration;
+import org.springframework.web.reactive.function.server.RouterFunction;
+import org.springframework.web.reactive.function.server.ServerResponse;
+import reactor.core.publisher.Mono;
+
+/**
+ * Tests the case which uses route handlers, and where "controller" span is created within a Mono
+ * map step, which follows a delay step. For exception endpoint, the exception is thrown within the
+ * last map step.
+ */
+class DelayedHandlerSpringWebFluxServerTest extends HandlerSpringWebFluxServerTest {
+  @Override
+  protected Class<?> getApplicationClass() {
+    return Application.class;
+  }
+
+  @Configuration
+  @EnableAutoConfiguration
+  static class Application {
+    @Bean
+    RouterFunction<ServerResponse> router() {
+      return new RouteFactory().createRoutes();
+    }
+
+    @Bean
+    NettyReactiveWebServerFactory nettyFactory() {
+      return new NettyReactiveWebServerFactory();
+    }
+  }
+
+  static class RouteFactory extends ServerTestRouteFactory {
+
+    @Override
+    protected Mono<ServerResponse> wrapResponse(
+        ServerEndpoint endpoint, Mono<ServerResponse> response, Runnable spanAction) {
+      return response
+          .delayElement(Duration.ofMillis(10))
+          .map(
+              original ->
+                  controller(
+                      endpoint,
+                      () -> {
+                        spanAction.run();
+                        return original;
+                      }));
+    }
+  }
+}