HTTP keep-alive connections not reusable with chunked transfer encoding

[NiteshKant]

As part of the fix for issue #126 here: #128, a bug was introduced where in the response for the first HTTP keep-alive request does not write the "LastHttpContent" and hence netty's HTTP decoder did not consider the response as complete.
This leads to a state where for subsequent responses, netty's HTTP decoder will ignore the HTTP headers as it thinks that the first response is not yet over.

This can be reproduced by this sample server:

import io.netty.buffer.ByteBuf;
import io.netty.handler.codec.http.HttpHeaders;
import io.netty.handler.codec.http.HttpMethod;
import io.netty.handler.codec.http.HttpVersion;
import io.netty.handler.logging.LogLevel;
import io.reactivex.netty.RxNetty;
import io.reactivex.netty.channel.SingleNioLoopProvider;
import io.reactivex.netty.protocol.http.client.HttpClient;
import io.reactivex.netty.protocol.http.client.HttpClientRequest;
import io.reactivex.netty.protocol.http.client.HttpClientResponse;
import io.reactivex.netty.protocol.http.server.HttpServerBuilder;
import io.reactivex.netty.protocol.http.server.HttpServerRequest;
import io.reactivex.netty.protocol.http.server.HttpServerResponse;
import io.reactivex.netty.protocol.http.server.RequestHandler;
import rx.Observable;
import rx.functions.Action1;

import java.util.concurrent.ExecutionException;

public final class Http10Server {

    public static void main(String[] args) {
        int eventLoopCounts;
        if (args.length > 0) {
            eventLoopCounts = Integer.parseInt(args[0]);
        } else {
            eventLoopCounts = 0;
        }
        final String MSG = "Hello World";
        final int HELLO_WORLD_LENGTH = MSG.getBytes().length;

        RxNetty.useEventLoopProvider(new SingleNioLoopProvider(eventLoopCounts));

        new HttpServerBuilder<ByteBuf, ByteBuf>(7008, new RequestHandler<ByteBuf, ByteBuf>() {
            @Override
            public Observable<Void> handle(HttpServerRequest<ByteBuf> request, HttpServerResponse<ByteBuf> response) {
                response.getHeaders().set(HttpHeaders.Names.CONTENT_LENGTH, HELLO_WORLD_LENGTH);
                return response.writeStringAndFlush(MSG);
            }
        }, true).enableWireLogging(LogLevel.ERROR).build().startAndWait();
    }
}

and using Apache Bench command:

ab -k -n 2 -c 1 'http://localhost:7008/'

The following server log:

May 31, 2014 9:57:11 AM io.netty.handler.logging.LoggingHandler channelActive
SEVERE: [id: 0xf1e62957, /127.0.0.1:50953 => /127.0.0.1:7008] ACTIVE
May 31, 2014 9:57:11 AM io.netty.handler.logging.LoggingHandler logMessage
SEVERE: [id: 0xf1e62957, /127.0.0.1:50953 => /127.0.0.1:7008] RECEIVED(106B)
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 47 45 54 20 2f 20 48 54 54 50 2f 31 2e 30 0d 0a |GET / HTTP/1.0..|
|00000010| 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 4b 65 65 70 |Connection: Keep|
|00000020| 2d 41 6c 69 76 65 0d 0a 48 6f 73 74 3a 20 6c 6f |-Alive..Host: lo|
|00000030| 63 61 6c 68 6f 73 74 3a 37 30 30 38 0d 0a 55 73 |calhost:7008..Us|
|00000040| 65 72 2d 41 67 65 6e 74 3a 20 41 70 61 63 68 65 |er-Agent: Apache|
|00000050| 42 65 6e 63 68 2f 32 2e 33 0d 0a 41 63 63 65 70 |Bench/2.3..Accep|
|00000060| 74 3a 20 2a 2f 2a 0d 0a 0d 0a                   |t: */*....      |
+--------+-------------------------------------------------+----------------+
May 31, 2014 9:57:11 AM io.netty.handler.logging.LoggingHandler logMessage
SEVERE: [id: 0xf1e62957, /127.0.0.1:50953 => /127.0.0.1:7008] WRITE(63B)
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 48 54 54 50 2f 31 2e 30 20 32 30 30 20 4f 4b 0d |HTTP/1.0 200 OK.|
|00000010| 0a 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 6b 65 65 |.Connection: kee|
|00000020| 70 2d 61 6c 69 76 65 0d 0a 43 6f 6e 74 65 6e 74 |p-alive..Content|
|00000030| 2d 4c 65 6e 67 74 68 3a 20 31 31 0d 0a 0d 0a    |-Length: 11.... |
+--------+-------------------------------------------------+----------------+
May 31, 2014 9:57:11 AM io.netty.handler.logging.LoggingHandler logMessage
SEVERE: [id: 0xf1e62957, /127.0.0.1:50953 => /127.0.0.1:7008] WRITE(11B)
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 48 65 6c 6c 6f 20 57 6f 72 6c 64                |Hello World     |
+--------+-------------------------------------------------+----------------+
May 31, 2014 9:57:11 AM io.netty.handler.logging.LoggingHandler flush
SEVERE: [id: 0xf1e62957, /127.0.0.1:50953 => /127.0.0.1:7008] FLUSH
May 31, 2014 9:57:11 AM io.netty.handler.logging.LoggingHandler flush
SEVERE: [id: 0xf1e62957, /127.0.0.1:50953 => /127.0.0.1:7008] FLUSH
May 31, 2014 9:57:11 AM io.netty.handler.logging.LoggingHandler logMessage
SEVERE: [id: 0xf1e62957, /127.0.0.1:50953 => /127.0.0.1:7008] RECEIVED(106B)
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 47 45 54 20 2f 20 48 54 54 50 2f 31 2e 30 0d 0a |GET / HTTP/1.0..|
|00000010| 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 4b 65 65 70 |Connection: Keep|
|00000020| 2d 41 6c 69 76 65 0d 0a 48 6f 73 74 3a 20 6c 6f |-Alive..Host: lo|
|00000030| 63 61 6c 68 6f 73 74 3a 37 30 30 38 0d 0a 55 73 |calhost:7008..Us|
|00000040| 65 72 2d 41 67 65 6e 74 3a 20 41 70 61 63 68 65 |er-Agent: Apache|
|00000050| 42 65 6e 63 68 2f 32 2e 33 0d 0a 41 63 63 65 70 |Bench/2.3..Accep|
|00000060| 74 3a 20 2a 2f 2a 0d 0a 0d 0a                   |t: */*....      |
+--------+-------------------------------------------------+----------------+
May 31, 2014 9:57:12 AM io.netty.handler.logging.LoggingHandler logMessage
SEVERE: [id: 0xf1e62957, /127.0.0.1:50953 => /127.0.0.1:7008] WRITE(11B)
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 48 65 6c 6c 6f 20 57 6f 72 6c 64                |Hello World     |
+--------+-------------------------------------------------+----------------+
May 31, 2014 9:57:12 AM io.netty.handler.logging.LoggingHandler flush
SEVERE: [id: 0xf1e62957, /127.0.0.1:50953 => /127.0.0.1:7008] FLUSH
May 31, 2014 9:57:12 AM io.netty.handler.logging.LoggingHandler flush
SEVERE: [id: 0xf1e62957, /127.0.0.1:50953 => /127.0.0.1:7008] FLUSH

shows that for the second request, the server does not send the headers, but just sends the content "Hello World"

Thanks @brendangregg for debugging this!

[victuxbb]

Hi @NiteshKant, is this bug fixed?
I'm trying to do a:

ab -k -c 1 -n 2 -v 3 http://192.168.59.103:8080/campaigns/27

And I recived:

apr_pollset_poll: The timeout specified has expired (70007)
Total of 1 requests completed

Searching in google about karyon and response "chunked" I came here...

Thanks!

[NiteshKant]

@victuxbb Can you share your server code?

For apache-bench, you would have to set the content-length header in your response, as it does not handle chunked encoding.

[victuxbb]

Ok ok sorry for the confusion, like you say it's a problem with "ab" about not handling chunked responses

Thanks for the clarification 👍