[HTTPCORE-599] Capacity feedback does not throttle AsyncDataConsumer.consume() for Http1

• Type: Bug
• Status: Resolved
• Priority: Blocker
• Resolution: Fixed
• Affects Version/s: 5.0-beta8
• Fix Version/s: 5.0-beta9
• Component/s: HttpCore NIO
• Environment: macOS Mojave using the IntelliJ CE 2019.2.1 runtime
• Assignee: Unassigned
• Reporter: Roy Hashimoto
• Created: 09/Sep/19 21:24
• Updated: 27/Sep/19 09:26
• Resolved: 12/Sep/19 08:12

Description

The capacity window mechanism in AbstractHttp1StreamDuplexer does not appear to be throttling calls to AsyncDataConsumer.consume(). This affects both client and server asynchronous entity consumers.

The attached test program implements a simple 5.0 asynchronous HTTP/1.1 server. Aside from boilerplate code, the significant parts are:

1. Set the HTTP1 initial window size to 8192.
2. Add an AsyncExchangeHandler that creates an empty response and logs the AsyncDataConsumer method calls to the console.
3. Updating the capacity channel is intentionally omitted, effectively providing an infinitely slow consumer.

To test, post data of more than 8 KB to the server (e.g. using curl). I expect to see in the log consume() calls totaling at least 8192 and nothing after that until the socket times out. Instead, what I see is consume() calls delivering all the data and then streamEnd().

Here is sample output for uploading almost 32 KB. I have used my IDE to add a logging breakpoint to show the capacity window on this line:

https://github.com/apache/httpcomponents-core/blob/a60528ea58877d55dab266bd2813e065aac6ff2c/httpcore5/src/main/java/org/apache/hc/core5/http/impl/nio/AbstractHttp1StreamDuplexer.java#L313

so those are also included in the output below.

Mon Sep 09, 2019 10:27:18.893 AM SlowConsumerTest main FINE: Listening on /0:0:0:0:0:0:0:0:8080
Mon Sep 09, 2019 10:27:31.294 AM SlowConsumerTest$MyExchangeHandler handleRequest FINEST: handleRequest called
Mon Sep 09, 2019 10:27:31.332 AM SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 8192
AbstractHttp1StreamDuplexer:313 capacity=0
Mon Sep 09, 2019 10:27:31.341 AM SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called
Mon Sep 09, 2019 10:27:31.342 AM SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 16384
AbstractHttp1StreamDuplexer:313 capacity=-8192
Mon Sep 09, 2019 10:27:31.346 AM SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called
Mon Sep 09, 2019 10:27:31.348 AM SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 24576
AbstractHttp1StreamDuplexer:313 capacity=-16384
Mon Sep 09, 2019 10:27:31.352 AM SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called
Mon Sep 09, 2019 10:27:31.354 AM SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8150 total 32726
AbstractHttp1StreamDuplexer:313 capacity=-24534
Mon Sep 09, 2019 10:27:31.357 AM SlowConsumerTest$MyExchangeHandler streamEnd FINEST: streamEnd called

Issue Links

• links to: GitHub Pull Request #148