Swagger-codegen: Adding custom logging intercetpor throws java.io.IOException: Stream closed

[mladendinev]

I generated a java client code from my own swagger definition using the swagger-codegen-cli and _resttemplate_ as codegen library, which worked flawlessly in the beginning. However, I wanted to add my own Logging interceptor which I've done at the initialization stage (Bean initialization) in my application:

@Bean
public DefaultApi defaultApi() {
RestTemplate restTemplate = new RestTemplate(new BufferingClientHttpRequestFactory(new SimpleClientHttpRequestFactory()));
List<ClientHttpRequestInterceptor> interceptors = new ArrayList<ClientHttpRequestInterceptor>();
interceptors.add(new CustomLoggingInterceptor());
restTemplate.setInterceptors(interceptors);
return new ApiClient(restTempalte);

When I make a request through the client, I receive a very deeply nested java.io.IOException: Stream closed.

[wing328]

cc @nbruno (resttemplate creator) to see if he's any clue.

[nbruno]

What's the full stacktrace? Also, your posted code has a typo (restTempalte) and is probably not compilable (DefaultApi is not assignable to ApiClient). Is this the actual code that produces the error?

[Chexpir]

@nbruno I reproduce the problem. it's very straightforward to reproduce, just using the default logging/debugging interceptor, I'd say we need to reopen it. it happens on 2.3.1
I am pretty sure the problem is on logging the response, which cannot be read twice.

2018-02-01 17:52:42.267 INFO 2195 --- [nio-8086-exec-3] piClient$ApiClientHttpRequestInterceptor : URI: http://localhost:18088/...-key/2134953542
2018-02-01 17:52:42.267 INFO 2195 --- [nio-8086-exec-3] piClient$ApiClientHttpRequestInterceptor : HTTP Method: GET
2018-02-01 17:52:42.267 INFO 2195 --- [nio-8086-exec-3] piClient$ApiClientHttpRequestInterceptor : HTTP Headers: Accept=[/],Content-Type=[application/json],User-Agent=[Java-SDK],Content-Length=[0]
2018-02-01 17:52:42.267 INFO 2195 --- [nio-8086-exec-3] piClient$ApiClientHttpRequestInterceptor : Request Body:
2018-02-01 17:52:42.344 INFO 2195 --- [nio-8086-exec-3] piClient$ApiClientHttpRequestInterceptor : HTTP Status Code: 200
2018-02-01 17:52:42.344 INFO 2195 --- [nio-8086-exec-3] piClient$ApiClientHttpRequestInterceptor : Status Text:
2018-02-01 17:52:42.344 INFO 2195 --- [nio-8086-exec-3] piClient$ApiClientHttpRequestInterceptor : HTTP Headers: X-Application-Context=[application:18088],Content-Type=[application/json;charset=UTF-8],Transfer-Encoding=[chunked],Date=[Thu, 01 Feb 2018 17:52:41 GMT]
2018-02-01 17:52:42.344 INFO 2195 --- [nio-8086-exec-3] piClient$ApiClientHttpRequestInterceptor : Response Body: {"header":{"statusCode":200},....

2018-02-01 17:52:42.345 ERROR 2195 --- [nio-8086-exec-3] c.t.l.f.r.c.e.ExceptionController :
REQUEST_ID: null, CLASS_NAME: ProductController, METHOD_NAME: publish, MESSAGE: General exception occured. Details:
2018-02-01 17:52:42.345 ERROR 2195 --- [nio-8086-exec-3] StackTraceLogger :
REQUEST_ID: null, CLASS_NAME: ProductController, METHOD_NAME: publish, STACK_TRACE: org.springframework.web.client.ResourceAccessException: I/O error on GET request for "http://localhost:18088/....-key/2134953542": Attempted read from closed stream.; nested exception is java.io.IOException: Attempted read from closed stream.
at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:666)
at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:628)
at org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:602)
at com.............client.dsm.ApiClient.invokeAPI(ApiClient.java:529)

[wing328]

@Chexpir I just reopened the issue. May I know if you've time to contribute a fix to the issue?

[Chexpir]

Locally, I have modified ApiClient not to log the response body, so I don't have the need to keep working on it. I'll take a look today and let you know if I find any alternative.

When I've worked in some other JBehave internal rest framework we couldn't read the response body twice, so I think is a design error, you cannot read the response body twice, so interceptors are not suit for purpose if we want to log the response body.

[Chexpir]

I've confirmed that the current model uses an InputStream to request the body, so non-minor design changes needed in order to maintain the response body logging, so I've decided it was better to remove the body logging, at least in 2.4.0.

Feel free to work for 3.0.0 in a different logging system without using interceptors.

[nbruno]

I am pretty sure the problem is on logging the response, which cannot be read twice.

This is only true if you're not using a buffering request factory (see this SO answer for the full implementation). The original pull request documents this requirement and the default implementation of building the RestTemplate object within ApiClient will use the BufferingClientHttpRequestFactory.

It's possible that the ApiClient is getting constructed via Spring in which case the RestTemplate comes from the Spring context and may or may not be configured to handle reading the response body more than once.

In any case, simply disabling debugging should remove the interceptor from being used.

[Chexpir]

In that case, I recommend to reject the PR, and close the reopened issue, as it´s not a defect but a specific restriction of the debugging functionality :-) Thanks for the help.

[jmiddleton]

Just in case someone comes across this issue, the way I solved is doing the following:

Instantiate RestTemplate using a BufferingClientHttpRequestFactory and the LoggingRequestInterceptor:

RestTemplate restTemplate = new RestTemplate(new BufferingClientHttpRequestFactory(new SimpleClientHttpRequestFactory()));
List<ClientHttpRequestInterceptor> interceptors = new ArrayList<>();
interceptors.add(new LoggingRequestInterceptor());
restTemplate.setInterceptors(interceptors);

The BufferingClientHttpRequestFactory is required as we want to use the response body both in the interceptor and for the initial calling code. The default implementation allows to read the response body only once.

[rambobbala]

Using this BufferingClientHttpRequestFactory we are missing a way to set ReadTimeout and ConnectTimeout. Normally we use HttpComponentsClientHttpRequestFactory for this. Any alternative solutions to this ?

[kmapte]

I recenlty was looking to debug whats going wrong with my request. I used the Swagger resttemplate to generate the client.
What I found that in the ApiClient there is a public method to setDebugging and you can set to true or false.
with that I was able to see the actual json that was transmitted that helped me narrow down the cause of 400 bad request

[elaissoussi]

In our case, we can't change the RestTemplate implementation, It's commun bean template for many Clients.

To resolve the problem, we had wrapped the response in BufferingClientHttpResponseWrapper before log it, and StreamUtils.copyToString so we prevent stream reading and closing by default.

class LoggingRequestInterceptor implements ClientHttpRequestInterceptor

@Override
    public ClientHttpResponse intercept(HttpRequest request, byte[] body, ClientHttpRequestExecution execution) throws IOException
    {
        traceRequest(request, body);
        final ClientHttpResponse response = execution.execute(request, body);
      final BufferingClientHttpResponseWrapper bufferingResponse = new BufferingClientHttpResponseWrapper(response);
        traceResponse(bufferingResponse);
        return bufferingResponse;
    }

traceResponse(response){
...
            LOG.debug(String.format("Response body: %s",  StreamUtils.copyToString(response.getBody(), Charset.defaultCharset())));
...
}

[reynierramos]

I share with you a complete example as I use it, I have also included the configuration of trusted certificates:

/**
 * The RestTemplateConfig global config
 */
@Configuration
public class RestTemplateConfig {

    @Value("${app.timeout}")
    private Integer timeout;

    /**
     * Get global RestTemplate from autoconfig builder
     *
     * @param builder the auto-configuration builder
     * @return restTemplate object
     * @throws GeneralSecurityException exception
     */
    @Bean
    public RestTemplate restTemplate(RestTemplateBuilder builder) throws GeneralSecurityException {
        TrustStrategy trust = (cert, authType) -> true;
        SSLContext sslContext = SSLContexts.custom().loadTrustMaterial(null, trust).build();
        SSLConnectionSocketFactory sslSf = new SSLConnectionSocketFactory(sslContext, NoopHostnameVerifier.INSTANCE);
        Registry<ConnectionSocketFactory> registry =
            RegistryBuilder.<ConnectionSocketFactory>create()
                .register("https", sslSf)
                .register("http", new PlainConnectionSocketFactory())
                .build();
        BasicHttpClientConnectionManager manager =
            new BasicHttpClientConnectionManager(registry);

        CloseableHttpClient client = HttpClients.custom()
            .setSSLSocketFactory(sslSf)
            .setConnectionManager(manager)
            .setDefaultRequestConfig(config())
            .build();
        ClientHttpRequestFactory factory = new BufferingClientHttpRequestFactory(
            new HttpComponentsClientHttpRequestFactory(client));

        return builder
            .errorHandler(new RestTemplateResponseErrorHandler())
            .interceptors(new RestTemplateLoggingInterceptor())
            .requestFactory(() -> factory)
            .build();
    }

    private RequestConfig config() {
        return RequestConfig.custom()
            .setConnectTimeout(timeout)
            .setConnectionRequestTimeout(timeout)
            .setSocketTimeout(timeout)
            .build();
    }
}


@Slf4j
public class RestTemplateLoggingInterceptor implements ClientHttpRequestInterceptor {
    @Override
    public ClientHttpResponse intercept(HttpRequest request, byte[] body, ClientHttpRequestExecution execution)
        throws IOException {
        logRequest(request, body);
        ClientHttpResponse response = execution.execute(request, body);
        logResponse(response);

        return response;
    }

    private void logRequest(HttpRequest request, byte[] body) throws IOException {
        if (log.isDebugEnabled()) {
            log.debug("==========================REQUEST BEGIN==========================");
            log.debug("URI         : {}", request.getURI());
            log.debug("Method      : {}", request.getMethod());
            log.debug("Headers     : {}", request.getHeaders());
            log.debug("Request body: {}", new String(body, StandardCharsets.UTF_8));
            log.debug("==========================REQUEST END============================");
        }
    }

    private void logResponse(ClientHttpResponse response) throws IOException {
        if (log.isDebugEnabled()) {
            log.debug("==========================REQUEST BEGIN==========================");
            log.debug("Status code  : {}", response.getStatusCode());
            log.debug("Status text  : {}", response.getStatusText());
            log.debug("Headers      : {}", response.getHeaders());
            log.debug("Response body: {}", StreamUtils.copyToString(response.getBody(), StandardCharsets.UTF_8));
            log.debug("==========================REQUEST END============================");
        }
    }
}