Using Spring Boot RestTemplate with X-Ray

[KentonParton]

I am using the AWS X-Ray auto-instrumentation agent for a Spring Boot 1.5 app but get a Segment not found error. When I change the Spring Boot version from 1.5.4.RELEASE to 2.3.4.RELEASE the app works as expected when using code snippet 2.

I ran into this issue while trying to use the SpringFramework RestTemplate as follows:

Code Snippet 1

import com.amazonaws.xray.proxies.apache.http.HttpClientBuilder;
import org.apache.http.impl.client.CloseableHttpClient;
import org.springframework.boot.web.client.RestTemplateBuilder;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.client.RestTemplate;
import org.springframework.http.client.HttpComponentsClientHttpRequestFactory;

@Configuration
public class RestTemplateConfig {
    @Bean
    public RestTemplate restTemplate(RestTemplateBuilder restTemplateBuilder){

        CloseableHttpClient client= HttpClientBuilder.create().build();
        HttpComponentsClientHttpRequestFactory clientHttpRequestFactory = new HttpComponentsClientHttpRequestFactory(client);
        return restTemplateBuilder.requestFactory(clientHttpRequestFactory).build();
    }
}

but noticed the same error occurred when trying the following:

Code Snippet 2

import com.amazonaws.xray.proxies.apache.http.HttpClientBuilder;
import com.fasterxml.jackson.databind.ObjectMapper;
import org.apache.http.HttpEntity;
import org.apache.http.client.methods.CloseableHttpResponse;
import org.apache.http.client.methods.HttpGet;
import org.apache.http.impl.client.CloseableHttpClient;
import org.apache.http.util.EntityUtils;
import org.springframework.stereotype.Service;

import java.io.IOException;
import java.io.InputStream;
import java.util.Map;

@Service
public class DemoService {

    public String requestOne() {
        CloseableHttpClient httpclient = HttpClientBuilder.create().build();
        HttpGet httpGet = new HttpGet("http://localhost:8084/demo1/demo1");
        CloseableHttpResponse response = httpclient.execute(httpGet);
        try {
            HttpEntity entity = response.getEntity();
            InputStream inputStream = entity.getContent();
            ObjectMapper mapper = new ObjectMapper();
            Map<String, String> jsonMap = mapper.readValue(inputStream, Map.class);
            String name = jsonMap.get("name");
            EntityUtils.consume(entity);
            return name;
        } finally {
            response.close();
        }
    }
}

I get the following stack trace:

Stack Trace

Suppressing AWS X-Ray context missing exception (SegmentNotFoundException): Failed to begin subsegment named 'localhost': segment cannot be found.
Suppressing AWS X-Ray context missing exception (SubsegmentNotFoundException): Failed to end subsegment: subsegment cannot be found.
Null ModelAndView returned to DispatcherServlet with name 'dispatcherServlet': assuming HandlerAdapter completed request handling
Successfully completed request
Suppressing AWS X-Ray context missing exception (SegmentNotFoundException): No segment in progress.
The X-Ray Agent had encountered an unexpected exception for the following event: software.amazon.disco.agent.event.HttpServletNetworkResponseEvent@1a1905d5
 

 

java.lang.NullPointerException: null

at com.amazonaws.xray.agent.runtime.handlers.upstream.ServletHandler.handleResponse(ServletHandler.java:96) ~[aws-xray-agent-plugin.jar:na]

at com.amazonaws.xray.agent.runtime.dispatcher.EventDispatcher.dispatchResponseEvent(EventDispatcher.java:75) ~[aws-xray-agent-plugin.jar:na]

at com.amazonaws.xray.agent.runtime.listeners.XRayListener.listen(XRayListener.java:38) ~[aws-xray-agent-plugin.jar:na]

at software.amazon.disco.agent.event.EventBus.publish(EventBus.java:66) [na:na]

at software.amazon.disco.agent.web.servlet.HttpServletServiceInterceptor.service(HttpServletServiceInterceptor.java:143) [disco-java-agent-web-plugin.jar:na]

at org.springframework.web.servlet.DispatcherServlet.service(DispatcherServlet.java) [spring-webmvc-4.3.9.RELEASE.jar:4.3.9.RELEASE]

at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat-embed-websocket-8.5.15.jar:8.5.15]

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) [spring-web-4.3.9.RELEASE.jar:4.3.9.RELEASE]

at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.9.RELEASE.jar:4.3.9.RELEASE]

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:105) [spring-web-4.3.9.RELEASE.jar:4.3.9.RELEASE]

at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.9.RELEASE.jar:4.3.9.RELEASE]

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81) [spring-web-4.3.9.RELEASE.jar:4.3.9.RELEASE]

at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.9.RELEASE.jar:4.3.9.RELEASE]

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) [spring-web-4.3.9.RELEASE.jar:4.3.9.RELEASE]

at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.9.RELEASE.jar:4.3.9.RELEASE]

at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:799) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:861) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1455) [tomcat-embed-core-8.5.15.jar:8.5.15]

at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-8.5.15.jar:8.5.15]

at software.amazon.disco.agent.concurrent.decorate.DecoratedRunnable.run(DecoratedRunnable.java:60) [na:na]

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_212]

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_212]

at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-8.5.15.jar:8.5.15]

at software.amazon.disco.agent.concurrent.decorate.DecoratedRunnable.run(DecoratedRunnable.java:60) [na:na]

at java.lang.Thread.run(Thread.java:748) [na:1.8.0_212]

at org.apache.tomcat.util.threads.TaskThread.run(TaskThread.java) [tomcat-embed-core-8.5.15.jar:8.5.15]

[willarmiros]

Hi @KentonParton,

Thanks for reporting this issue. It seems like there are 2 problems. The first problem is that the Agent should not be recording an NPE, even during unexpected behavior like not having a segment available to close, so I'll try and make that more graceful.

The second, deeper issue is that there wasn't a segment available in this method. I'm a little confused by which of your code snippets work since you said "app works as expected when using code snippet 2" but also said code snippet 2 had the NPE. Do you see any segment for this DemoService at all? It seems like there is no segment available by the time the agent detects a Servlet response from your service. This could mean either the segment was closed prematurely (in which case you should see it in your X-Ray console) or there was no segment to begin with, which means the agent never picked up on a servlet request.

As for tracing the RestTemplate client, the agent can only auto-instrument Apache HTTP clients. We likely will not add support for RestTemplate clients since it is on a deprecation path. Also, no big deal, but we have a separate Java Agent Repo where you can open related issues in the future!

[KentonParton]

Thanks for your response @willarmiros and addressing the NPE.

Regarding the confusion, code snippet 2 works as expected on Spring Boot 2.0 + but errors on Spring Boot 1.5.4. I believe there was no segment to begin with as it was not picked up in the console.

[KentonParton]

Is there an ETA for this fix by any chance? It would allow my team and I to plan accordingly. Thank you.

[willarmiros]

Hi @KentonParton,
I'll have to reproduce this locally with the older version of spring boot, unfortunately we can't give ETAs but I will update this when I do a deep dive. For some more context, are you calling requestOne from another Spring request mapping method? Because one thing that I think could be happening is when you make a request to your other endpoint, http://localhost:8084/demo1/demo1, the agent begins a new segment for the incoming request to demo1/demo1 and discards the one for the actual incoming request that you are handling.

If you could post your raw trace data from the tests that work as expected, and also the raw trace data from the Spring 1.5.4 tests (if there is any) to compare it to that would be very helpful.

[KentonParton]

Hi @willarmiros, I have created a repo here which has the two Spring services. To run them you will just need to set the following -javaagent:./disco/disco-java-agent.jar=pluginPath=./disco/disco-plugins and run the xray agent.

I am making the request as follows:

localhost:8080/demo/requestOne (PostMan) --> http://localhost:8084/demo1/demo1 (bi-tracing-1) --> (bi-tracing-2)

As mentioned before, if you change from Spring Boot 1.5.4.RELEASE to 2.3.4.RELEASE the tracing works as expected.

Please let me know if you need further info.

[willarmiros]

Hi @KentonParton,
Thank you for all this repro info. I will look into the problem and see if I can reproduce and diagnose the root cause.

[KentonParton]

Hi @willarmiros, just wanted to check if there has been any progress on this?

[willarmiros]

@KentonParton sorry for not following up yet, have been all over the place recently. This will be the next issue I investigate and will post an update when I do.

[willarmiros]

@KentonParton I've just gotten around to testing this. I cloned your repo and, as it is provided (using Spring Boot 1.5.4.RELEASE), tracing worked just fine for me. Here's what I did:

git clone https://github.com/KentonParton/xray-tracing-demo.git
cd xray-tracing-demo/bi-tracing-1
./mvnw package
java -javaagent:./disco/disco-java-agent.jar=pluginPath=./disco/disco-plugins -Dlogging.level.com.amazonaws.xray=DEBUG  -jar target/bi-tracing-demo-0.0.1-SNAPSHOT.jar

# Separate shell
cd xray-tracing-demo/bi-tracing-2
./mvnw package
java -javaagent:./disco/disco-java-agent.jar=pluginPath=./disco/disco-plugins -Dlogging.level.com.amazonaws.xray=DEBUG  -jar target/bi-tracing-demo-0.0.1-SNAPSHOT.jar

Then, I went to http://localhost:8080/demo/requestOne in my browser and the request was served successfully and logs showed no errors. My computer is not cooperating but I will post a picture of the trace too.

[KentonParton]

@willarmiros Thank you for trying to replicate the issue.

When I run the application from the terminal it works for me too. I must have something set incorrectly in Intellij as I still get the error. I will dig a bit deeper tomorrow. Thanks again.