ConnectionClosedException: Premature end of Content-Length delimited message body since updating to 2.4.8/2.5.2

[sailingHobbit]

We tried updating our microservices from Spring Boot 2.4.5 first to 2.4.8 and then (as 2.4.8 showed the behavior described below) to 2.5.2 which unfortunately has the same issue.

Observed behavior

When clients call the REST API of our services they get the following error: org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 129,072; received: 116,446) While expected value varies per received response, received is usually the same (might be affected by new deployments of the service providing the REST API). It does not apply to all responses but only around 1% and only those with "large" response bodies (100-300 kb). Also it does not start directly after the service has been deployed but usually after a couple of dozen requests have been made.

Assumptions

We suspect the issue to be on the server side as a rollback to Spring Boot 2.4.5 solved the problem. Therefore it's unlikely to be a client or infrastructure issue. Also it affects multiple services, some deployed in AWS ECS and some in AWS EKS which makes an infrastrucutre issue also unlikely.

Code & Stack trace

There is no try/catch block involved in building the response (one of the first things google brought up when searching for the exception message). Unfortunately I cannot include the original source code (confidential) but tried to create something which is similar from a technical perspective: Controller:

import org.apache.commons.codec.binary.Base64;
import org.apache.commons.lang3.RandomStringUtils;
import org.springframework.http.ResponseEntity;
import org.springframework.web.bind.annotation.PostMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

import java.nio.charset.StandardCharsets;
import java.util.Random;

@RestController
@RequestMapping(value = "/largeDummyResponse")
public class DummyLargeResponseApiController {

    private static final String DUMMY_VERSION = "application/x.company.project.dummy.v1+json";
    private static final int CRITICAL_SIZE = 116446; // the size all responses have been cut to on 2021-07-05

    private static Random random = new Random();

    @PostMapping(produces = DUMMY_VERSION, consumes = DUMMY_VERSION)
    public ResponseEntity<DummyResponseDto> createLargeDummyResponse(DummyRequestDto request) {
        String largeString = RandomStringUtils.random(CRITICAL_SIZE + 10000 + random.nextInt(15000));
        DummyResponseDto result = DummyResponseDto.builder()
                .version(request.getVersion())
                .largeContent(Base64.encodeBase64String(largeString.getBytes(StandardCharsets.UTF_8)))
                .build();
        return ResponseEntity.ok(result);
    }
}

DTO (Request is just the version attrbiute):

import lombok.AllArgsConstructor;
import lombok.Builder;
import lombok.EqualsAndHashCode;
import lombok.Getter;
import lombok.NoArgsConstructor;
import lombok.ToString;

@Getter
@NoArgsConstructor
@AllArgsConstructor
@EqualsAndHashCode
@Builder
@ToString
public class DummyResponseDto {
    private String version;
    private String largeContent;
}

Stacktrace (client side), omitted parts of internal code:

org.springframework.web.client.RestClientException: Error while extracting response for type [class net.minidev.json.JSONObject] and content type [application/x.company.project.dummy.v1+json]; nested exception is org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 129,072; received: 116,446)
    at org.springframework.web.client.HttpMessageConverterExtractor.extractData(HttpMessageConverterExtractor.java:120)
    at org.springframework.web.client.RestTemplate$ResponseEntityResponseExtractor.extractData(RestTemplate.java:1037)
    at org.springframework.web.client.RestTemplate$ResponseEntityResponseExtractor.extractData(RestTemplate.java:1020)
    at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:778)
    at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:711)
    at org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:602)
    at org.springframework.boot.test.web.client.TestRestTemplate.exchange(TestRestTemplate.java:715)
    ...
Caused by: org.apache.http.ConnectionClosedException: Premature end of Content-Length delimited message body (expected: 129,072; received: 116,446)
    at org.apache.http.impl.io.ContentLengthInputStream.read(ContentLengthInputStream.java:178)
    at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:135)
    at java.base/java.io.FilterInputStream.read(FilterInputStream.java:133)
    at java.base/java.io.PushbackInputStream.read(PushbackInputStream.java:183)
    at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._loadMore(UTF8StreamJsonParser.java:220)
    at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._loadMoreGuaranteed(UTF8StreamJsonParser.java:2401)
    at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._finishString2(UTF8StreamJsonParser.java:2486)
    at com.fasterxml.jackson.core.json.UTF8StreamJsonParser._finishAndReturnString(UTF8StreamJsonParser.java:2466)
    at com.fasterxml.jackson.core.json.UTF8StreamJsonParser.getText(UTF8StreamJsonParser.java:297)
    at com.fasterxml.jackson.databind.deser.std.UntypedObjectDeserializer$Vanilla.deserialize(UntypedObjectDeserializer.java:670)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer._readAndBindStringKeyMap(MapDeserializer.java:540)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:377)
    at com.fasterxml.jackson.databind.deser.std.MapDeserializer.deserialize(MapDeserializer.java:29)
    at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:4526)
    at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3521)
    at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.readJavaType(AbstractJackson2HttpMessageConverter.java:378)
    at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.read(AbstractJackson2HttpMessageConverter.java:342)
    at org.springframework.web.client.HttpMessageConverterExtractor.extractData(HttpMessageConverterExtractor.java:105)
    at org.springframework.web.client.RestTemplate$ResponseEntityResponseExtractor.extractData(RestTemplate.java:1037)
    at org.springframework.web.client.RestTemplate$ResponseEntityResponseExtractor.extractData(RestTemplate.java:1020)
    at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:778)
    at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:711)
    at org.springframework.web.client.RestTemplate.exchange(RestTemplate.java:602)
    at org.springframework.boot.test.web.client.TestRestTemplate.exchange(TestRestTemplate.java:715)
    ...
    at jdk.internal.reflect.GeneratedMethodAccessor191.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at io.cucumber.java.Invoker.doInvoke(Invoker.java:66)
    at io.cucumber.java.Invoker.invoke(Invoker.java:24)
    at io.cucumber.java.AbstractGlueDefinition.invokeMethod(AbstractGlueDefinition.java:47)
    at io.cucumber.java.JavaStepDefinition.execute(JavaStepDefinition.java:29)
    at io.cucumber.core.runner.CoreStepDefinition.execute(CoreStepDefinition.java:66)
    at io.cucumber.core.runner.PickleStepDefinitionMatch.runStep(PickleStepDefinitionMatch.java:63)
    at io.cucumber.core.runner.ExecutionMode$1.execute(ExecutionMode.java:10)
    at io.cucumber.core.runner.TestStep.executeStep(TestStep.java:92)
    at io.cucumber.core.runner.TestStep.run(TestStep.java:64)
    at io.cucumber.core.runner.PickleStepTestStep.run(PickleStepTestStep.java:51)
    at io.cucumber.core.runner.TestCase.run(TestCase.java:104)
    at io.cucumber.core.runner.Runner.runPickle(Runner.java:73)
    at io.cucumber.junit.PickleRunners$WithStepDescriptions.run(PickleRunners.java:110)
    at io.cucumber.junit.FeatureRunner.runChild(FeatureRunner.java:135)
    at io.cucumber.junit.FeatureRunner.runChild(FeatureRunner.java:27)
    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
    at io.cucumber.junit.Cucumber.runChild(Cucumber.java:200)
    at io.cucumber.junit.Cucumber.runChild(Cucumber.java:90)
    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
    at io.cucumber.junit.Cucumber$RunCucumber.evaluate(Cucumber.java:235)
    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
    at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
    at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
    at org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:43)
    at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
    at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195)
    at java.base/java.util.Iterator.forEachRemaining(Iterator.java:133)
    at java.base/java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801)
    at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
    at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
    at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
    at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
    at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
    at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
    at org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:82)
    at org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:73)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:220)
    at org.junit.platform.launcher.core.DefaultLauncher.lambda$execute$6(DefaultLauncher.java:188)
    at org.junit.platform.launcher.core.DefaultLauncher.withInterceptedStreams(DefaultLauncher.java:202)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:181)
    at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:128)
    at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:150)
    at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:124)
    at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384)
    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345)
    at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126)
    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)

Server logs On the server side we do not see any errors or warnings in the log for these requests. We even enabled debug logging and the last log from the server side is from org.springframework.web.servlet.DispatcherServlet with the msg Completed 200 OK. The usual log from our own (AOP based) logging framework for a completed request is missing. There is also a log message from an nginx controller (used to route requests from the company network to the AWS EKS cluster) which shows a latency of about 1 minute for the erroneous requests. In normal cases this is aber 50-200 milliseconds. It also shows the response size as seen in the exception message as received. Of course this log line is only present for requests directly from the company network. Requests from within the EKS cluster do not pass through that nginx controller.

Any ideas on what might cause the issue? As it affects both 2.4.8 and 2.5.2 we suspect some common dependency which is still in an older version in Boot 2.4.5.

Best regards Ben

[wilkinsona]

Thanks for the report.

Spring MVC doesn't set a Content-Length header for JSON responses as doing so would require it to buffer the response in memory. The fact that your responses have a Content-Length header tells me that we don't have enough information to help you here. There must be something in your app that's doing that buffering, setting the Content-Length header, and then writing JSON to the response, but you haven't told us what it is.

It would also be useful to know which container you're using. You've mentioned DispatcherServlet so it's probably Tomcat but it would be good to know for sure.

If you would like us to spend some more time investigating, please spend some time providing a complete yet minimal sample that reproduces the problem. You can share it with us by pushing it to a separate repository on GitHub or by zipping it up and attaching it to this issue.

[sailingHobbit]

Thanks for your feedback! I did not know about Spring MVC not setting a Content-Length header (and obviously no one in my team did either or I think they would have mentioned that). I will have a look into it and search for the dependency that might actually be causing the issue. This is a really helpful information and would explain why no one else seems to be having that issue with 2.4.8/2.5.2. :-)

Yes you're right, we are using Tomcat.

I will try to build a fully working example but that will require some time since we have a rather complex Maven structure and also some company internal dependencies (one of which might even be the reason for den Content-Length header).

I will post again as soon as I either have a working sample project with the issue running or found out what is creating the Content-Length header.

[sailingHobbit]

The hint concerning the Content-Length did the trick and pointed us in the right direction. The root cause seems to be us logging payloads of response by using org.springframework.web.util.ContentCachingResponseWrapper. The relevant code is the following (I just removed some internal imports):

import org.springframework.http.HttpStatus;
import org.springframework.web.filter.OncePerRequestFilter;
import org.springframework.web.util.ContentCachingResponseWrapper;
import org.springframework.web.util.WebUtils;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.nio.charset.StandardCharsets;

public abstract class AbstractPayloadLoggingFilter extends OncePerRequestFilter {

    private final PayloadLoggingCatalog payloadLoggingCatalog = CatalogFactory.create()
            .createCatalog(PayloadLoggingCatalog.class, getModuleName());

    private PayloadLoglevel payloadLoglevel;

    protected abstract String getModuleName();

    protected void setPayloadLoglevel(PayloadLoglevel payloadLoglevel) {
        this.payloadLoglevel = payloadLoglevel;
    }

    @Override
    protected void doFilterInternal(HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse,
            FilterChain filterChain) throws ServletException, IOException {
        HttpServletRequest cachedRequest = new RequestWrapper(httpServletRequest);
        HttpServletResponse cachedResponse = new ContentCachingResponseWrapper(httpServletResponse);
        try {
            filterChain.doFilter(cachedRequest, cachedResponse);
        } finally {
            if (PayloadLoglevel.ALL == payloadLoglevel ||
                    (PayloadLoglevel.ERROR == payloadLoglevel && isError(httpServletResponse))) {

                String correlationId = cachedRequest.getHeader(Constants.HEADER_CORRELATION_ID);

                payloadLoggingCatalog.signalRequest(((RequestWrapper) cachedRequest).getBody())
                        .mergedWithCustomTopLevelAttributes(Attributes.create().with(Constants.KEY_CORRELATION_ID, correlationId))
                        .log();
                payloadLoggingCatalog.signalResponse(getResponseData(cachedResponse))
                        .mergedWithCustomTopLevelAttributes(Attributes.create().with(Constants.KEY_CORRELATION_ID, correlationId))
                        .log();
            }
            ((ContentCachingResponseWrapper) cachedResponse).copyBodyToResponse();
        }
    }

    private static boolean isError(HttpServletResponse httpServletResponse) {
        HttpStatus status = HttpStatus.valueOf(httpServletResponse.getStatus());
        return status.is4xxClientError() || status.is5xxServerError();
    }

    private static String getResponseData(final HttpServletResponse response) throws IOException {
        String payload = "null";
        ContentCachingResponseWrapper wrapper =
                WebUtils.getNativeResponse(response, ContentCachingResponseWrapper.class);
        if (wrapper != null) {
            byte[] buf = wrapper.getContentAsByteArray();
            if (buf.length > 0) {
                payload = new String(buf, 0, buf.length, StandardCharsets.UTF_8);
                wrapper.copyBodyToResponse();
            }
        }
        return payload;
    }

}

If I build a context that does not include an Implementation of this PayloadLoggingFilter the issue does not occur and also responses do not include a Content-Length header.

Looking into ContentCachingResponseWrapper I suspect that it is responsible for setting the Content-Length header. Since Spring Boot 2.4.8 and 2.5.2 both include Spring Web 5.3.8 while Boot 2.4.5 has Web 5.3.6, there might have been a change between those versions of Spring Web that causes the invalid Content-Length header.

Therefore this is obviously not a Spring Boot issue but rather Spring Web. Can the issue be moved or should I open a new one within Spring Web?

[bclozel]

I'm not sure this is a Spring Framework issue.

Your filter implementation might be involved here, since it's calling copyBodyToResponse multiple times and async dispatches are not considered.

Maybe by the time it's calling copyBodyToResponse a first time, the content is written and the Content-Length header is set; some more content might be written later to the cached body, but another call to copyBodyToResponse will not update the Content-Length since it's already been set. This would explain what you're seeing.

I think the ShallowEtagHeaderFilter implementation could help here.

[sailingHobbit]

Sounds legit that there might be something else that adds "bytes" to the response (although I doubt that we have a Filter in our code that changes the response body itself). Therefore I am with you that it is not an issue within Spring (which would also explain why we could not find anyone else with a similar issue using Google). After discussing it with the team we decided to completely remove the payload logging as we do not really use it anymore. This will fix the problem for us. Thank you all a lot for the helpful input, especially pointing us in the right direction what actually caused the issue! :)