spring-4.3.0 instrumentation is not working when @EnableFeignClients is used - resulting in invalid transaction name

mgr32 commented 1 year ago

Description

When Spring Boot 3 is used and Spring Cloud OpenFeign's @EnableFeignClients annotation (docs) is added (with specific parameters) to the main class, New Relic's spring-4.3.0 instrumentation stops working and transaction names no longer contain controller method name or endpoint path.

Note the annotation should not logically affect Spring controllers. It is also unknown why "equivalent" parameters of the annotation (basePackages vs basePackageClasses) affect the resulting transaction name. The exact result depends on Spring Boot / Spring Cloud version and specific parameters of the annotation:

Spring Boot	Spring Cloud / OpenFeign	Annotation	Transaction name at one.newrelic.com	Expected?
2.7.10	2021.0.6 / 3.1.6	none or `@EnableFeignClients(basePackages = "com.example.demo")`	WebTransaction/SpringController/hello (GET)	:heavy_check_mark: Y
2.7.10	2021.0.6 / 3.1.6	`@EnableFeignClients(basePackageClasses = TestClient.class)` or `@EnableFeignClients(clients = TestClient.class)`	WebTransaction/SpringController/TestController/sayHello	:warning: N (not sure why changed?)
3.0.5	2022.0.2 / 4.0.2	none or `@EnableFeignClients(basePackages = "com.example.demo")`	WebTransaction/SpringController/hello (GET)	:heavy_check_mark: Y
3.0.5	2022.0.2 / 4.0.2	`@EnableFeignClients(basePackageClasses = TestClient.class)` or `@EnableFeignClients(clients = TestClient.class)`	WebTransaction/Servlet/dispatcherServlet	:x: N (does not have required information)

More details at https://github.com/mgr32/newrelic-spring-cloud-openfeign-issue

Expected Behavior

spring-4.3.0 instrumentation should work in each case, and transaction name should be consistent (possibly always WebTransaction/SpringController/hello (GET))

Troubleshooting

When the transaction name is not "WebTransaction/SpringController/hello (GET)" the following entry is logged by the NewRelic Java Agent:

com.newrelic FINEST: Skipping instrumentation module com.newrelic.instrumentation.spring-4.3.0. The most likely cause is that com.newrelic.instrumentation.spring-4.3.0 shouldn't apply to this application.

Steps to Reproduce

Described at https://github.com/mgr32/newrelic-spring-cloud-openfeign-issue

Your Environment

Ubuntu 22.04.2 x64
New Relic Java Agent 8.0.1
OpenJDK Temurin-17.0.6+10 x64
Spring Boot 3 / Spring Cloud 2022 (also Spring Boot 2 / Spring Cloud 2021)

Reproduced locally and at cloud instances.

workato-integration[bot] commented 1 year ago

https://issues.newrelic.com/browse/NEWRELIC-7931

kford-newrelic commented 1 year ago

@mgr32 thank you for alerting us to this behavior. We are reviewing internally

kford-newrelic commented 1 year ago

@mgr32 our Team has agreed to pull this into our backlog. We cannot commit to a date at the moment but as we plan our work for future quarters, we will consider this issue. Thank you!

pattrykks commented 1 year ago

@kford-newrelic can this prioritised? Spring4x is not longer maintained from long time (https://endoflife.date/spring-framework). For many users "Transaction" is most important feature of NewRelic. In our case workaround proposed by @mgr32 doesn't seems to work properly. If NewRelic stops providing us with this feature (in the next few months we will have to migrate to the latest Spring anyway) it means for us that we will have to start looking for an alternative solution for NewRelic. What is the recommendation for users for which mentioned feature stoped working with update to Spring Boot 3.0+?

mgr32 commented 1 year ago

@kford-newrelic I was able to create a simpler example without Feign, and I think it's an issue with caching of PackageValidationResult objects in WeavePackageManager#validPackages. Please see the updated example here: https://github.com/mgr32/newrelic-spring-cloud-openfeign-issue/tree/simpler-example-with-analysis and the analysis section in the readme.

In order to work around the issue, I believe we would need to ensure that all @RestController and @Controller classes are loaded before any other non-controller classes containing request mapping annotations (such as @FeignClient classes with methods annotated with @GetMapping).

mgr32 commented 1 year ago

Additional findings

There is an additional issue with SpringPointCut not migrated from javax to jakarta. That's why there is a difference between transaction naming in Spring Boot 2 (Spring Framework 5) and Spring Boot 3 (Spring Framework 6) when spring-4.3.0 instrumentation is not applied.

Summary

There seem to be 2 separate issues: 1) spring-4.3.0 instrumentation not being applied for Spring controllers, depending on the order of class loading. It occurs both in Spring Boot 2 and Spring Boot 3 applications, but Spring Boot 2 weaving has a fallback - SpringPointCut, which does not work in Spring Boot 3 (see below).

SpringPointCut expecting HandlerAdapter#handle method accepting objects of types javax.servlet.http.*. It does not work in spring-web >= 6.0.0 (coming with Spring Boot 3), as its HandlerAdapter#handle accepts objects of types jakarta.servlet.http.*.

See simpler-example-with-analysis for a minimal reproducible example.

Note that the transactions are named in the following way:

if spring-4.3.0 instrumentation is applied the transaction name will be WebTransaction/SpringController/hello (GET) (spring-4.3.0 will be applied in a non-deterministic way both in Spring Boot 2 and Spring Boot 3)
if spring-4.3.0 instrumentation is not applied, but SpringPointCut instrumentation is applied, the transaction name will be WebTransaction/SpringController/TestController/sayHello (SpringPointCut will be applied only in Spring Boot 2)
if no above instrumentations are applied, the transaction name will be WebTransaction/Servlet/dispatcherServlet.

The fix for the second issue (SpringPointCut) seems to be straightforward (migrate from javax to jakarta). Regarding the first issue (spring-4.3.0), see the next section.

Further analysis of spring-4.3.0 issue

The root cause of the (spring-4.3.0 issue) seems to be a too-broad cache key in WeavePackageManager#validPackages, resulting in PackageValidationResult from one class (with weaving violations) being used for another class (without weaving violations).

Consider the following classes:

com.example.demo.TestNonController - class for which spring-4.3.0 should not apply (as there is @GetMapping but there is no @RestController mapping)
com.example.demo.TestController - class for which spring-4.3.0 instrumentation should apply

The following happens when TestNonController class is loaded before TestController class:

ClassLoader#loadClass("com.example.demo.TestNonController")
|- ClassWeaverService#transform
|--- WeavePackageManager#weave
|----- WeavePackageManager#match
|------- WeavePackageManager#validateAgainstClassLoader
|--------- ! hasValidated returns false (because validPackages does not contain entry for spring-4.3.0 weave package)
|--------- WeavePackage#validate -> returns PackageValidationResult with 0 violations
|--------- store PackageValidationResult in validPackages 
|------- returns PackageValidationResult with 0 violations
|----- PackageValidationResult#weave (for class name "com.example.demo.TestNonController")
|------- PackageValidationResult#getAnnotationMatchComposite
|--------- PackageValidationResult#buildResults
|----------- ClassMatch#match -> returns violation CLASS_MISSING_REQUIRED_ANNOTATIONS (correctly, as this class does not have `@RestController` and `@Controller` annotations)
|----------- !!! add the violation to violations collection
|--------- don't weave the class because violations collection is not empty (correctly)

ClassLoader#loadClass("com.example.demo.TestController")
|- ClassWeaverService#transform
|--- WeavePackageManager#weave
|----- WeavePackageManager#match   
|------- WeavePackageManager#validateAgainstClassLoader
|--------- !!! hasValidated returns true (because validPackages contains PackageValidationResult with the violation added during loading "com.example.demo.TestNonController" class)
|------- returns PackageValidationResult with 1 violation (from TestNonController class)
|----- PackageValidationResult#weave (for class name "com.example.demo.TestController")
|------- PackageValidationResult#getAnnotationMatchComposite
|--------- PackageValidationResult#buildResults
|----------- ClassMatch#match -> returns no violation (correctly, as this class has `@RestController` annotation)
|----------- !!! adds no violation to the collection, but the collection already contains 1 violation (from TestNonController class)
|--------- !!! don't weave the class because violations collection is not empty (incorrectly)

Thus, if TestNonController is loaded first, no controllers will be woven afterwards, as the violations from TestNonController will be cached in WeavePackageManager#validPackages and reused for next classes.

jtduffy commented 1 year ago

Hi @mgr32, Thanks for your repro apps and your detailed analysis of the issue! We're looking to pull this into our backlog, probably in Q3. We'll keep you updated on our progress. Thanks again.

kford-newrelic commented 1 year ago

@mgr32 really appreciate your insight into this issue!

We tried to target this for the coming Jul-Sep quarter but it doesn't look like we'll have the bandwidth. Going to try for the Oct-Dec (Q3) quarter.

mgr32 commented 1 year ago

Hi @jtduffy @kford-newrelic, thanks a lot for fixing the issue earlier than estimated, it looks like it helps :)

mgr32 commented 1 year ago

@jtduffy, @kford-newrelic, one more question - any chance of migrating SpringPointCut class from javax to jakarta (the second issue described in https://github.com/newrelic/newrelic-java-agent/issues/1197#issuecomment-1562828071)?

It is still used e.g. for handling not matched HTTP requests (returning 404) - in Spring Boot 2 they are logged e.g. as WebTransaction/SpringController/BasicErrorController/errorHtml, and in Spring Boot 3 WebTransaction/Servlet/dispatcherServlet

newrelic / newrelic-java-agent