Spring Integration: inbound-gateway management is slower by 20 seconds instead of @Controller management

Question

I have two Spring MVC applications; I'm using Spring Integration HTTP to integrate them.

The process

The process is very simple: an HTTP GET request directed to the "application1" is managed by a @Controller and then "transfered" to the "application2" with an <int-http:outbound-gateway> through an HTTP POST.

Once there, this POST (intermediate) request is managed and transfered to another URI of the "application2" (with another <int-http:outbound-gateway>), that provides the real response.

The issue

I have noticed a different behaviour in the request management on the "application2" side (which is invoked by the <int-http:outbound-gateway> of the "application1").

If I use a @Controller to manage the "intermediate" URI, the process execution needs some milliseconds to be accomplished.

But if I use an <int-http:inbound-gateway> to replicate the same process, it needs 20 seconds to complete the process: why this difference?

This is the implementation with the @Controller:

@Controller
@RequestMapping(value="/service")
public class ServiceController {

    @RequestMapping(value="/{resource}", method=RequestMethod.POST)
    public void resource(@PathVariable(value="resource") String resource, HttpServletRequest request, HttpServletResponse res){
        handleRequest(resource,request, res);
    }

    private void handleRequest(String resource, HttpServletRequest request, HttpServletResponse res) throws Exception {
        // READING THE REQUEST PAYLOAD
        RequestHandler requestHandler = RequestHandler.getHandler(request);         
        RequestPayload payload = requestHandler.getPayload();

        // PREPARING THE MESSAGE TO THE CHANNEL
        MessagingChannel messagingChannel = (MessagingChannel)ApplicationContextResolver.getApplicationContext().getBean("requestChannelBean");
        MessageChannel requestChannel = messagingChannel.getRequestChannel();
        MessagingTemplate messagingTemplate = new MessagingTemplate();
        String url = request.getScheme()+"://"+request.getServerName()+":"+request.getServerPort()+request.getServletContext().getContextPath()+request.getServletPath()+"/"+resource;
        Message<?> requestMessage = MessageBuilder.withPayload(url).build();

        // SEND THE MESSAGE AND RECEIVE THE RESPONSE
        Message<?> response = messagingTemplate.sendAndReceive(requestChannel, requestMessage);

        // PRINT THE RESPONSE
        res.getWriter().write((String)response.getPayload());

    }
}

This solution works perfectly and it needs a few milliseconds to return the response.

The following is the implementation with the <int-http:inbound-gateway> and the <int:service-activator> that I'm trying to use to replicate the @Controller solution:

<int:service-activator id="channelServiceActivator"
    ref="channelService"
    input-channel="requestChannel"      
    method="manage"/>

<int-http:inbound-gateway id="gateway" request-channel="requestChannel"
              path="/service/**" 
              supported-methods="POST"
              header-mapper="headerMapper">
    <int-http:header name="requestAttributes" expression="#requestAttributes"/>
</int-http:inbound-gateway>

With this service activator:

public class ChannelService {

    public String manage(Message<?> message) throws Throwable{

        // RECOVERING THE HttpServletRequest
        ServletRequestAttributes sra = (ServletRequestAttributes) message.getHeaders().get("requestAttributes");
        HttpServletRequest request = sra.getRequest();

        // RETRIEVING THE PAYLOAD
        Object payload = message.getPayload();

        // PREPARING THE MESSAGE TO THE CHANNEL
        MessagingChannel messagingChannel = (MessagingChannel)ApplicationContextResolver.getApplicationContext().getBean("requestChannelBean");
        MessageChannel requestChannel = messagingChannel.getRequestChannel();
        MessagingTemplate messagingTemplate = new MessagingTemplate();
        String url = request.getScheme()+"://"+request.getServerName()+":"+request.getServerPort()+request.getServletContext().getContextPath()+request.getServletPath()+"/"+resource;
        Message<?> requestMessage = MessageBuilder.withPayload(url).build();

        // SEND THE MESSAGE AND RECEIVE THE RESPONSE
        Message<?> response = messagingTemplate.sendAndReceive(requestChannel, requestMessage);

        // RETURN THE RESPONSE
        return (String) response.getPayload(); // <- since here, the behaviour is normal. 
                                               // The framework needs 20 seconds after this instruction

    }
}   

This implementation needs 20 seconds to be completed for every request, I don't understand the reason for that. I don't see any error in the Spring logs, I only see that the system seems to "freeze": it not logs anything anymore for 20 seconds.

Any explanation would be appreciated.

UPDATE

Here the logs. After the "HttpMessageConverterExtractor.extractData:101", it needs 20 seconds before seing the others "org.springframework.integration.http" logs (2016-07-29 15:06:18 -> 2016-07-29 15:06:38).

2016-07-29 15:06:18 TRACE [] org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.close:217 (http-nio-8080-exec-4) - Logical connection closed
GenericMessage [payload={
  "_embedded" : {
    "persons" : [ ]
  },
  "_links" : {
    "self" : {
      "href" : "http://localhost:8080/application2/api/persons"
    },
    "profile" : {
      "href" : "http://localhost:8080/application2/api/profile/persons"
    },
    "search" : {
      "href" : "http://localhost:8080/application2/api/persons/search"
    }
  }
}, headers={Transfer-Encoding=chunked, Server=Apache-Coyote/1.1, Accept=application/json, X-Content-Type-Options=nosniff, Pragma=no-cache, http_statusCode=200, Date=1469797578000, X-Frame-Options=DENY, Cache-Control=no-cache, no-store, max-age=0, must-revalidate, id=2b6b0b80-82bc-2ce7-c364-1e84c389bc71, X-XSS-Protection=1; mode=block, contentType=application/json, timestamp=1469797578411}]
2016-07-29 15:06:18 DEBUG [] org.springframework.web.client.RestTemplate.handleResponse:658 (executor-1) - POST request for "http://localhost:8080/application2/api/service/persons" resulted in 200 (OK)
2016-07-29 15:06:18 DEBUG [] org.springframework.web.client.HttpMessageConverterExtractor.extractData:101 (executor-1) - Reading [java.lang.String] as "application/octet-stream" using [org.springframework.http.converter.StringHttpMessageConverter@5397e277]
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:436 (executor-1) - inboundHeaderNames=[*]
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[server] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:463 (executor-1) - setting headerName=[Server], value=[Apache-Coyote/1.1]
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[pragma] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:463 (executor-1) - setting headerName=[Pragma], value=no-cache
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[accept] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:463 (executor-1) - setting headerName=[Accept], value=[application/json]
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[host] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:463 (executor-1) - setting headerName=[host], value=[localhost:8080]
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[connection] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:463 (executor-1) - setting headerName=[connection], value=[keep-alive]
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[cache-control] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:463 (executor-1) - setting headerName=[Cache-Control], value=no-cache
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[user-agent] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:463 (executor-1) - setting headerName=[user-agent], value=[Java/1.8.0_65]
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[x-xss-protection] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:454 (executor-1) - setting headerName=[X-XSS-Protection], value=[1; mode=block]
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[x-frame-options] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:454 (executor-1) - setting headerName=[X-Frame-Options], value=[DENY]
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[x-content-type-options] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:454 (executor-1) - setting headerName=[X-Content-Type-Options], value=[nosniff]
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[content-type] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:463 (executor-1) - setting headerName=[Content-Type], value=application/octet-stream
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[content-length] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:463 (executor-1) - setting headerName=[Content-Length], value=968
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.shouldMapHeader:537 (executor-1) - headerName=[date] WILL be mapped, matched pattern=*
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:463 (executor-1) - setting headerName=[Date], value=1.469.797.578.000
answer: {
  "_embedded" : {
    "persons" : [ ]
  },
  "_links" : {
    "self" : {
      "href" : "http://localhost:8080/application2/api/persons"
    },
    "profile" : {
      "href" : "http://localhost:8080/application2/api/profile/persons"
    },
    "search" : {
      "href" : "http://localhost:8080/application2/api/persons/search"
    }
  }
}
2016-07-29 15:06:38 TRACE [] org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest:138 (http-nio-8080-exec-2) - Method [sendMessageToChannel] returned [null]
2016-07-29 15:06:38 DEBUG [] org.springframework.web.servlet.DispatcherServlet.processDispatchResult:1044 (http-nio-8080-exec-2) - Null ModelAndView returned to DispatcherServlet with name 'dispatcher': assuming HandlerAdapter completed request handling
2016-07-29 15:06:38 TRACE [] org.springframework.web.servlet.FrameworkServlet.resetContextHolders:1062 (http-nio-8080-exec-2) - Cleared thread-bound request context: SecurityContextHolderAwareRequestWrapper[ org.springframework.security.web.context.HttpSessionSecurityContextRepository$Servlet3SaveToSessionRequestWrapper@9bacc4f]
2016-07-29 15:06:38 DEBUG [] org.springframework.web.servlet.FrameworkServlet.processRequest:1000 (http-nio-8080-exec-2) - Successfully completed request
2016-07-29 15:06:38 TRACE [] org.springframework.context.support.AbstractApplicationContext.publishEvent:362 (http-nio-8080-exec-2) - Publishing event in WebApplicationContext for namespace 'dispatcher-servlet': ServletRequestHandledEvent: url=[/application1/api/persons/]; client=[0:0:0:0:0:0:0:1]; method=[GET]; servlet=[dispatcher]; session=[null]; user=[null]; time=[21426ms]; status=[OK]
2016-07-29 15:06:38 TRACE [] org.springframework.context.support.AbstractApplicationContext.publishEvent:362 (http-nio-8080-exec-2) - Publishing event in Root WebApplicationContext: ServletRequestHandledEvent: url=[/application1/api/persons/]; client=[0:0:0:0:0:0:0:1]; method=[GET]; servlet=[dispatcher]; session=[null]; user=[null]; time=[21426ms]; status=[OK]
2016-07-29 15:06:38 DEBUG [] org.springframework.security.web.access.ExceptionTranslationFilter.doFilter:117 (http-nio-8080-exec-2) - Chain processed normally
2016-07-29 15:06:38 DEBUG [] org.springframework.security.web.header.writers.HstsHeaderWriter.writeHeaders:130 (http-nio-8080-exec-2) - Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@7ffcc692
2016-07-29 15:06:38 DEBUG [] org.springframework.security.web.context.HttpSessionSecurityContextRepository$SaveToSessionResponseWrapper.saveContext:352 (http-nio-8080-exec-2) - SecurityContext is empty or contents are anonymous - context will not be stored in HttpSession.
2016-07-29 15:06:38 DEBUG [] org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter:119 (http-nio-8080-exec-2) - SecurityContextHolder now cleared, as request processing completed

UPDATE 2

I have investigated more the process:

• The outbound-gateway (application1) sends a message to a remote endpoint (application2) with the "sendAndReceive()"; the message contains the header "application/octet-stream", because I pass a Byte Array as payload.
• The remote endpoint (application2) has an inbound-gateway with a service activator
• The service activator (application2) processes the request and returns a String.
• The HttpMessageConverterExtractor (application1) try to read the response with the contentType of the message that has been sent to the "application2" (application/octet-stream).

I think that the problem is right here: I have sent a message with the outbound-gateway with the header application/octet-stream, but in response I have to receive a String (with application/json), not an application/octet-stream.

These are the informations of the inputMessage variable used by the readInternal method of the class org.springframework.http.converter.StringHttpMessageConverter:

inputMessage    MessageBodyClientHttpResponseWrapper  (id=111)  
    pushbackInputStream PushbackInputStream  (id=146)   
    response    SimpleClientHttpResponse  (id=121)  
        connection  HttpURLConnection  (id=125) 
        headers HttpHeaders  (id=182)   {Server=[Apache-Coyote/1.1], Pragma=[no-cache], Accept=[application/json], host=[localhost:8080], connection=[keep-alive], Cache-Control=[no-cache], user-agent=[Java/1.8.0_65], X-XSS-Protection=[1; mode=block], X-Frame-Options=[DENY], X-Content-Type-Options=[nosniff], Content-Type=[application/octet-stream], Content-Length=[968], Date=[Mon, 01 Aug 2016 12:52:47 GMT]}
        responseStream  HttpURLConnection$HttpInputStream  (id=180) 

The Content-Type is application/octet-stream, but this must to be refered only to the message in outbound, not for the inbound message obtained in answer!

There is any way to configure the content type of the response that can receive an outbound-gateway?

My Service activator of application2 process the answer in this way:

public class ChannelService {

    public String manage(Message<?> message) throws Throwable{          
        ServletRequestAttributes sra = (ServletRequestAttributes) message.getHeaders().get("requestAttributes");
        HttpServletRequest request = sra.getRequest();
        System.out.println(request.getRequestURL());

        Object payload = message.getPayload();

        return "{ \"test\" : \"test\"}";
    }

}

UPDATE 3

The problem is the InputStream obtained by the HttpInputMessage with inputMessage.getBody().

While this InputStream is processed with the "read()" method, the result of the "read()" is never -1 for 20 seconds. I have implemented a custom StringHttpMessageConverter:

@Override
protected String readInternal(Class<? extends String> clazz, HttpInputMessage inputMessage)
        throws IOException, HttpMessageNotReadableException {
    System.out.println("ResponseStringHttpMessageConverter.readInternal()");

    int content;
    long start = System.currentTimeMillis();
    ByteArrayOutputStream baos = new ByteArrayOutputStream();
    while ( ( content = inputMessage.getBody().read()) != -1){
        System.out.println(content);
        baos.write(content);
    }   
    long end = System.currentTimeMillis();
    System.out.println("TIME READING: "+(end-start));
    String response = baos.toString();
    System.out.println(response);
    return response;
}

The custom readInternal method prints every single character ASCII code, after the last character it stops printing and when it restarts it prints:

TIME READING: 20164

So I suppose that there is something wrong in the InputStream of the message, because the read() method doesn't return "-1" before 20 seconds.

UPDATE 4

I solved the problem in the Converter side, but there is the same problem in the closing of the response in the doExecute() method of the org.springframework.web.client.RestTemplate class.

The method try to close the response (an instance of org.springframework.http.client.SimpleClientHttpResponse):

@Override
public void close() {
    if (this.responseStream != null) {
        try {
            StreamUtils.drain(this.responseStream); // <- again the same problem
            this.responseStream.close();
        }
        catch (IOException e) { }
    }
}

This is the "drain" implementation of org.springframework.util.StreamUtils class:

public static int drain(InputStream in) throws IOException {
    Assert.notNull(in, "No InputStream specified");
    byte[] buffer = new byte[BUFFER_SIZE];
    int bytesRead = -1;
    int byteCount = 0;
    while ((bytesRead = in.read(buffer)) != -1) { // it blocks here !!!
        byteCount += bytesRead;
    }
    return byteCount;
}

In my converter I solved the problem using a buffer with the expected available buffer size:

byte[] buffer = new byte[in.available()];
in.read(buffer);
baos.write(buffer); // (a simple ByteArrayOutputStream)

I definitely convinced that there is something wrong in my configuration of the outbound-gateway / inbound-gateway / service activator, because the response cause a block just before reading the -1 byte of EOS. Otherwise there would be a bug, and I don't believe in this option.

Answer 1

I have solved the problem, but in order to solve it, I had to create a custom RestTemplate.

In my custom RestTemplate I have overrided the method "doExecute()".

The implementation is the same of the original RestTemplate.doExecute, except the finally block.

In this block, I don't call "response.close()" but I have created a custom method that provides to close the response Client.

This is the custom RestTemplate implementation:

public class AppRestTemplate extends RestTemplate {

    @Override
    protected <T> T doExecute(URI url, HttpMethod method, RequestCallback requestCallback,
            ResponseExtractor<T> responseExtractor) throws RestClientException {

        Assert.notNull(url, "'url' must not be null");
        Assert.notNull(method, "'method' must not be null");
        ClientHttpResponse response = null;
        try {
            ClientHttpRequest request = createRequest(url, method);
            if (requestCallback != null) {
                requestCallback.doWithRequest(request);
            }
            response = request.execute();
            handleResponse(url, method, response);
            if (responseExtractor != null) {
                return responseExtractor.extractData(response);
            }
            else {
                return null;
            }
        }
        catch (IOException ex) {
            String resource = url.toString();
            String query = url.getRawQuery();
            resource = (query != null ? resource.substring(0, resource.indexOf(query) - 1) : resource);
            throw new ResourceAccessException("I/O error on " + method.name() +
                    " request for \"" + resource + "\": " + ex.getMessage(), ex);
        }
        finally {
            if (response != null) {
                 // response.close(); // <- commented; this is the cause of the slow process
                close(response);
            }
        }
    }

    /** This method only provides to close the stream, without draining it */
    private void close(ClientHttpResponse response) {
        try {
            if (response.getBody()!=null){
                response.getBody().close();
            }
        } catch (IOException e) {
            e.printStackTrace();
        }
    }

}

Obviously I had to register the new RestTemplate in the Application Context configuration:

<bean id="restTemplate" name="restTemplate" class="mypackage.integration.AppRestTemplate" autowire-candidate="true">
    <property name="messageConverters">
        <list>
            <bean class="mypackage.integration.ResponseStringHttpMessageConverter" />
            <!-- ... other converters -->
        </list>
    </property>
</bean>

Last but not least, I also had to implement a custom converter that replace the original StringHtppMessageConverter (in my case, ResponseStringHttpMessageConverter):

public class ResponseStringHttpMessageConverter extends AbstractHttpMessageConverter<String> {

    private Logger log = LoggerFactory.getLogger(ResponseStringHttpMessageConverter.class);

    public ResponseStringHttpMessageConverter() {
        super(new MediaType("application","json"));
    }

    @Override
    protected boolean supports(Class<?> clazz) {
        if (clazz == String.class)
            return true;
        else return false;
    }

    @Override
    protected String readInternal(Class<? extends String> clazz, HttpInputMessage inputMessage)
            throws IOException, HttpMessageNotReadableException {       
        int content;
        ByteArrayOutputStream baos = new ByteArrayOutputStream();
        byte[] buffer = new byte [inputMessage.getBody().available()];
        inputMessage.getBody().read(buffer);
        baos.write(buffer);
        String response = baos.toString();
        baos.close();
        return response;
    }

    @Override
    protected void writeInternal(String content, HttpOutputMessage outputMessage)
            throws IOException, HttpMessageNotWritableException {

    }

}

With this implementation, the requests don't suffer anymore of the slow problem.

P.S. I'm using Spring 4.3.1.RELEASE and Spring Integration 4.3.0.RELEASE.

I think that this is not to be considered a definitely solution, because I had to customize two framework components.

Answer 2

According to you logs:

2016-07-29 15:06:18 DEBUG [] org.springframework.web.client.HttpMessageConverterExtractor.extractData:101 (executor-1) - Reading [java.lang.String] as "application/octet-stream" using [org.springframework.http.converter.StringHttpMessageConverter@5397e277]
2016-07-29 15:06:38 DEBUG [] org.springframework.integration.http.support.DefaultHttpHeaderMapper.toHeaders:436 (executor-1) - inboundHeaderNames=[*]

It looks like you have very big response which takes that time for converting to String.

See HttpMessageConverterExtractor.extractData(ClientHttpResponse response).

There is nothing what Spring Integration does for.

Would be better if you'd debug that StringHttpMessageConverter.readInternal(Class<? extends String> clazz, HttpInputMessage inputMessage) and have a look what is your real response.