You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Dave Thorn <da...@fysh.org.INVALID> on 2019/08/30 20:34:02 UTC

Malformed chunked stream

I am reading a ~900K XML response from a Tomcat 7.0.76 server, using
Spring RestTemplate and very very intermittently I'm getting a
MalformedChunkCodingException.[1]

"Unexpected content at the end of chunk".

I enabled httpclient 'wire' debugging in my client and left it running
all day and I finally got a bite:

[many things]
DEBUG org.apache.http.wire -  << "datadatadata"
DEBUG org.apache.http.wire -  << "[\r][\n]"
DEBUG org.apache.http.wire -  << "1AB8[\r][\n]"
DEBUG org.apache.http.wire -  << "datadatadata"
DEBUG org.apache.http.wire -  << "[\r][\n]"
DEBUG org.apache.http.wire -  << "B50[\r][\n]"
DEBUG org.apache.http.wire -  << "datadatadata"
DEBUG org.apache.http.wire -  << "3FC0[\r][\n]"
[exception]

That looks, to me, like the stream is missing the [\r][\n] between the
B50 chunk and the 3FC0 count.

I'm not clear on where the responsibilities lie in producing that
chunked output - Spring in my webapp, or Tomcat as my container?

Thanks for any guidance you can provide.


[1]
Caused by: org.apache.http.MalformedChunkCodingException: Unexpected content at the end of chunk
	at org.apache.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:259)
	at org.apache.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:227)
	at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:186)
	at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:137)
	at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
	at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
	at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
	at java.io.InputStreamReader.read(InputStreamReader.java:184)
	at java.io.Reader.read(Reader.java:140)
	at org.springframework.util.StreamUtils.copyToString(StreamUtils.java:74)
	at org.springframework.http.converter.StringHttpMessageConverter.readInternal(StringHttpMessageConverter.java:85)
	at org.springframework.http.converter.StringHttpMessageConverter.readInternal(StringHttpMessageConverter.java:40)
	at org.springframework.http.converter.AbstractHttpMessageConverter.read(AbstractHttpMessageConverter.java:153)
	at org.springframework.web.client.HttpMessageConverterExtractor.extractData(HttpMessageConverterExtractor.java:103)
	at org.springframework.web.client.RestTemplate$ResponseEntityResponseExtractor.extractData(RestTemplate.java:724)
	at org.springframework.web.client.RestTemplate$ResponseEntityResponseExtractor.extractData(RestTemplate.java:709)
	at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:527)

-- 
dave thorn

Hi, I'm from the Internet.


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: Malformed chunked stream

Posted by Dave Thorn <da...@fysh.org.INVALID>.
On Tue, Sep 24, 2019 at 11:57:33AM +0100, Mark Thomas wrote:
> 
> One small positive to come of this was that I reviewed Tomcat's chunking
> code and made a small optimisation. The code is now a little cleaner, a
> little easier to maintain and might even be marginally faster (although
> I doubt any improvement is measurable).

And definitely no subtle bug introduced at the same time.

It would be painfully ironic were it so.

-- 
dave thorn

Bad to the bone.

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: Malformed chunked stream

Posted by Mark Thomas <ma...@apache.org>.
On 24/09/2019 10:02, Dave Thorn wrote:
> On Sun, Sep 01, 2019 at 08:51:47AM +0000, Mark Thomas wrote:
>> On August 31, 2019 7:31:12 AM UTC, Dave Thorn <da...@fysh.org.INVALID> wrote:
>>
>>> There is also a haproxy between client and server.  You wouldn't think
>>> it goes fiddling around in the middle of a response, thought.  I'm
>>> running some tests today that go straight to the server, skipping the
>>> proxy, but again with the intermittency...
>>
>> Indeed. Chunking is sufficiently fundamental that I'm surprised that
>> any component has a bug in this area.
> 
> (Following up for the record, even though this doesn't (seem to) relate
> to tomcat.)
> 
> I have spent the last nearly-a-month running tests on this, and it
> looks like the problem lies in haproxy.

Thanks for the update.

I'd agree that the evidence seems to be pointing towards haproxy at the
moment. If that changes then do let us know.

One small positive to come of this was that I reviewed Tomcat's chunking
code and made a small optimisation. The code is now a little cleaner, a
little easier to maintain and might even be marginally faster (although
I doubt any improvement is measurable).

Thanks again for keeping us updated.

Mark


> 
> When using haproxy version 1.7.something I haven't been able to
> trigger the error.  When using version 2.0.something I have triggered
> it a handful of times.
> 
> 
> This issue on github at least suggests it's not just me having some
> kind of intermittent issue with chunking in haproxy:
> 
> https://github.com/haproxy/haproxy/issues/171
> 
> 


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: Malformed chunked stream

Posted by Dave Thorn <da...@fysh.org.INVALID>.
On Sun, Sep 01, 2019 at 08:51:47AM +0000, Mark Thomas wrote:
> On August 31, 2019 7:31:12 AM UTC, Dave Thorn <da...@fysh.org.INVALID> wrote:
> 
> >There is also a haproxy between client and server.  You wouldn't think
> >it goes fiddling around in the middle of a response, thought.  I'm
> >running some tests today that go straight to the server, skipping the
> >proxy, but again with the intermittency...
> 
> Indeed. Chunking is sufficiently fundamental that I'm surprised that
> any component has a bug in this area.

(Following up for the record, even though this doesn't (seem to) relate
to tomcat.)

I have spent the last nearly-a-month running tests on this, and it
looks like the problem lies in haproxy.

When using haproxy version 1.7.something I haven't been able to
trigger the error.  When using version 2.0.something I have triggered
it a handful of times.


This issue on github at least suggests it's not just me having some
kind of intermittent issue with chunking in haproxy:

https://github.com/haproxy/haproxy/issues/171


-- 
dave thorn

Mostly Harmless.

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: Malformed chunked stream

Posted by Mark Thomas <ma...@apache.org>.
On August 31, 2019 7:31:12 AM UTC, Dave Thorn <da...@fysh.org.INVALID> wrote:
>On Sat, Aug 31, 2019 at 05:13:06AM +0000, Mark Thomas wrote:
>> On August 30, 2019 8:34:02 PM UTC, Dave Thorn
><da...@fysh.org.INVALID> wrote:
>> >
>> >That looks, to me, like the stream is missing the [\r][\n] between
>the
>> >B50 chunk and the 3FC0 count.
>> >
>> >I'm not clear on where the responsibilities lie in producing that
>> >chunked output - Spring in my webapp, or Tomcat as my container?
>
>> I'd also recommend repeating your test with Wireshark to confirm
>> that the server doesn't send it and that you aren't seeing a client
>> side bug.
>
>Thanks.  The only problem with that is the intermittency of the
>problem.  The server processes a hundred thousand requests a day, or
>so, and the problem only occurs a scant handful of times in that.
>I'll talk to our admin and see how feasible it is to do that and still
>be able to process the results.

I was thinking run Wireshark on your client machine rather than the server.

>There is also a haproxy between client and server.  You wouldn't think
>it goes fiddling around in the middle of a response, thought.  I'm
>running some tests today that go straight to the server, skipping the
>proxy, but again with the intermittency...

Indeed. Chunking is sufficiently fundamental that I'm surprised that any component has a bug in this area.

>> I took a quick look at Tomcat's ChunkedOutputFilter and I don't see
>> any obvious way the \r\n could be skipped but a strange edge case
>> isn't impossible.
>
>Looking at my access log file for yesterday, the test scenario made
>5375 requests, and if I look for those in the log, they all have the
>same response size:
>
># cat /opt/apache-tomcat-8.5.8/logs/localhost_access_log.2019-08-30.txt
>| grep 'various-identifiers' | awk '{print $10}' | sort | uniq -c
>   5375 970304
>
>Could that suggest that Tomcat responded with the same response every
>time?  If it dropped a "[\r][\n]" then that response size should be
>different, shouldn't it?

I'd need to check that and I'm on my phone right now. I don't recall which byte count gets logged.

 > Although I suppose if it could be being
>corrupted by a bug then it might be possible that the response size is
>calculated in a way that isn't affected by that hypothetical bug?

That is certainly possible.

Mark

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: Malformed chunked stream

Posted by Dave Thorn <da...@fysh.org.INVALID>.
On Sat, Aug 31, 2019 at 05:13:06AM +0000, Mark Thomas wrote:
> On August 30, 2019 8:34:02 PM UTC, Dave Thorn <da...@fysh.org.INVALID> wrote:
> >
> >That looks, to me, like the stream is missing the [\r][\n] between the
> >B50 chunk and the 3FC0 count.
> >
> >I'm not clear on where the responsibilities lie in producing that
> >chunked output - Spring in my webapp, or Tomcat as my container?

> I'd also recommend repeating your test with Wireshark to confirm
> that the server doesn't send it and that you aren't seeing a client
> side bug.

Thanks.  The only problem with that is the intermittency of the
problem.  The server processes a hundred thousand requests a day, or
so, and the problem only occurs a scant handful of times in that.
I'll talk to our admin and see how feasible it is to do that and still
be able to process the results.

There is also a haproxy between client and server.  You wouldn't think
it goes fiddling around in the middle of a response, thought.  I'm
running some tests today that go straight to the server, skipping the
proxy, but again with the intermittency...

> I took a quick look at Tomcat's ChunkedOutputFilter and I don't see
> any obvious way the \r\n could be skipped but a strange edge case
> isn't impossible.

Looking at my access log file for yesterday, the test scenario made
5375 requests, and if I look for those in the log, they all have the
same response size:

# cat /opt/apache-tomcat-8.5.8/logs/localhost_access_log.2019-08-30.txt | grep 'various-identifiers' | awk '{print $10}' | sort | uniq -c
   5375 970304

Could that suggest that Tomcat responded with the same response every
time?  If it dropped a "[\r][\n]" then that response size should be
different, shouldn't it?  Although I suppose if it could be being
corrupted by a bug then it might be possible that the response size is
calculated in a way that isn't affected by that hypothetical bug?

-- 
dave thorn

DBT; GBP.

---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

Re: Malformed chunked stream

Posted by Mark Thomas <ma...@apache.org>.
On August 30, 2019 8:34:02 PM UTC, Dave Thorn <da...@fysh.org.INVALID> wrote:
>I am reading a ~900K XML response from a Tomcat 7.0.76 server, using
>Spring RestTemplate and very very intermittently I'm getting a
>MalformedChunkCodingException.[1]
>
>"Unexpected content at the end of chunk".
>
>I enabled httpclient 'wire' debugging in my client and left it running
>all day and I finally got a bite:
>
>[many things]
>DEBUG org.apache.http.wire -  << "datadatadata"
>DEBUG org.apache.http.wire -  << "[\r][\n]"
>DEBUG org.apache.http.wire -  << "1AB8[\r][\n]"
>DEBUG org.apache.http.wire -  << "datadatadata"
>DEBUG org.apache.http.wire -  << "[\r][\n]"
>DEBUG org.apache.http.wire -  << "B50[\r][\n]"
>DEBUG org.apache.http.wire -  << "datadatadata"
>DEBUG org.apache.http.wire -  << "3FC0[\r][\n]"
>[exception]
>
>That looks, to me, like the stream is missing the [\r][\n] between the
>B50 chunk and the 3FC0 count.
>
>I'm not clear on where the responsibilities lie in producing that
>chunked output - Spring in my webapp, or Tomcat as my container?
>
>Thanks for any guidance you can provide.

I suspect Tomcat is doing the chunking but I'd recommend checking with the Spring folks to confirm that.

I'd also recommend repeating your test with Wireshark to confirm that the server doesn't send it and that you aren't seeing a client side bug.

I took a quick look at Tomcat's ChunkedOutputFilter and I don't see any obvious way the \r\n could be skipped but a strange edge case isn't impossible.

Mark


>
>
>[1]
>Caused by: org.apache.http.MalformedChunkCodingException: Unexpected
>content at the end of chunk
>	at
>org.apache.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:259)
>	at
>org.apache.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:227)
>	at
>org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:186)
>	at
>org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:137)
>	at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
>	at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
>	at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
>	at java.io.InputStreamReader.read(InputStreamReader.java:184)
>	at java.io.Reader.read(Reader.java:140)
>	at
>org.springframework.util.StreamUtils.copyToString(StreamUtils.java:74)
>	at
>org.springframework.http.converter.StringHttpMessageConverter.readInternal(StringHttpMessageConverter.java:85)
>	at
>org.springframework.http.converter.StringHttpMessageConverter.readInternal(StringHttpMessageConverter.java:40)
>	at
>org.springframework.http.converter.AbstractHttpMessageConverter.read(AbstractHttpMessageConverter.java:153)
>	at
>org.springframework.web.client.HttpMessageConverterExtractor.extractData(HttpMessageConverterExtractor.java:103)
>	at
>org.springframework.web.client.RestTemplate$ResponseEntityResponseExtractor.extractData(RestTemplate.java:724)
>	at
>org.springframework.web.client.RestTemplate$ResponseEntityResponseExtractor.extractData(RestTemplate.java:709)
>	at
>org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:527)


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org