Improve the cleanup of streaming responses #1119

trustin · 2018-04-04T15:56:46Z

Motivation:

A successfully sent response can be logged with AbortedStreamException
or ClosedChannelException due to race conditions.

Modifications:

Make HttpResponseSubscriber handle AbortedStreamException and
ClosedChannelException better so that they are not logged
unnecessarily
Make HttpServerHandler clean up unfinished HTTP/1 responses a little
bit later so that they are not aborted too early.
Miscellaneous:
- Fix a bug in DeferredStreamMessage where NeverInvokedSubscriber is
  invoked, which happens when a DeferredStreamMessage is delegated to
  another DeferredStreamMessage.

Result:

Much less chance of redundant AbortedStreamException or
ClosedChannelException

trustin · 2018-04-04T15:59:05Z

core/src/main/java/com/linecorp/armeria/server/HttpResponseSubscriber.java

+            // One of the two cases:
+            // - Client closed the connection too early.
+            // - Response publisher aborted the stream.
+            failAndReset((AbortedStreamException) cause);


/cc @kojilin You may want to send a canary to make sure this PR fixes your problem.

trustin · 2018-04-04T16:00:49Z

core/src/main/java/com/linecorp/armeria/server/HttpServerHandler.java

@@ -197,16 +197,41 @@ public int unfinishedRequests() {
    }

    @Override
-    public void channelUnregistered(ChannelHandlerContext ctx) throws Exception {
-        super.channelUnregistered(ctx);
-        unfinishedResponses.keySet().forEach(StreamMessage::abort);


No idea why channelUnregistered is used instead of channelInactive but they don't make any difference, so I moved the cleanup logic to channelInactive.

The netty documentation on these callbacks wasn't very clear, so I implemented every method and added breakpoints to try to figure it out. This was called where I expected and unregistering from armeria when unregistering from netty made intuitive sense, but if they're similar semantics seems good.

unregistration will always follow channelInactive. Netty allows deregistration without closing for a very special case, but we don't use it.

trustin · 2018-04-04T16:01:46Z

core/src/main/java/com/linecorp/armeria/server/HttpServerHandler.java

@@ -373,17 +398,15 @@ private void handleRequest(ChannelHandlerContext ctx, DecodedHttpRequest req) th
                }
            })).exceptionally(CompletionActions::log);

-            res.completionFuture().handle(voidFunction((ret, cause) -> {
+            res.completionFuture().handleAsync(voidFunction((ret, cause) -> {


Not really related with this PR, but thought this is cleaner.

trustin · 2018-04-04T16:02:20Z

jetty/src/main/java/com/linecorp/armeria/server/jetty/JettyService.java

-                if (data == null || !res.tryWrite(data)) {
-                    break;
+            if (res.tryWrite(headers)) {
+                for (;;) {


/cc @kojilin This should fix the IllegalStateException issue you reported.

trustin · 2018-04-04T16:02:32Z

tomcat/src/main/java/com/linecorp/armeria/server/tomcat/TomcatService.java

-                            if (d == null || !res.tryWrite(d)) {
-                                break;
+                        if (res.tryWrite(headers)) {
+                            for (;;) {


/cc @kojilin This should fix the IllegalStateException issue you reported.

trustin · 2018-04-04T16:03:14Z

tomcat/src/test/java/com/linecorp/armeria/server/tomcat/TomcatServiceTest.java

@@ -97,6 +98,7 @@ public void jarBasedWebApp() throws Exception {
                        .startsWith("application/java");
                assertThat(res.getFirstHeader(HttpHeaderNames.CONTENT_LENGTH.toString()).getValue())
                        .isEqualTo("1361");
+                EntityUtils.consume(res.getEntity());


Without this, Apache HC will close the connection before reading the response fully.

trustin · 2018-04-04T16:03:19Z

tomcat/src/test/java/com/linecorp/armeria/server/tomcat/TomcatServiceTest.java

@@ -110,6 +112,7 @@ public void jarBasedWebAppWithAlternativeRoot() throws Exception {
                        .startsWith("application/java");
                assertThat(res.getFirstHeader(HttpHeaderNames.CONTENT_LENGTH.toString()).getValue())
                        .isEqualTo("1361");
+                EntityUtils.consume(res.getEntity());


Without this, Apache HC will close the connection before reading the response fully.

trustin · 2018-04-04T16:17:01Z

core/src/main/java/com/linecorp/armeria/server/HttpServerHandler.java

+            case H1C:
+            case H1:
+                // XXX(trustin): How much time is 'a little bit'?
+                ctx.channel().eventLoop().schedule(this::cleanup, 1, TimeUnit.SECONDS);


I'm not sure if we should make this delay configurable. Thoughts?

Configuring just this knob is probably overkill - setting it based on idle timeout handler might make sense, but might also be overkill.

codecov · 2018-04-04T16:26:47Z

Codecov Report

Merging #1119 into master will decrease coverage by 0.08%.
The diff coverage is 78.57%.

@@            Coverage Diff            @@
##           master   #1119      +/-   ##
=========================================
- Coverage   72.48%   72.4%   -0.09%     
=========================================
  Files         510     510              
  Lines       22784   22801      +17     
  Branches     2826    2830       +4     
=========================================
- Hits        16514   16508       -6     
- Misses       4764    4782      +18     
- Partials     1506    1511       +5

Impacted Files	Coverage Δ
...com/linecorp/armeria/server/HttpServerHandler.java	`77.43% <100%> (-0.27%)`	⬇️
...om/linecorp/armeria/server/jetty/JettyService.java	`63.05% <25%> (-0.19%)`	⬇️
.../linecorp/armeria/server/tomcat/TomcatService.java	`62.13% <25%> (-4.26%)`	⬇️
...p/armeria/common/stream/DeferredStreamMessage.java	`87.06% <60%> (-0.32%)`	⬇️
...inecorp/armeria/server/HttpResponseSubscriber.java	`77.83% <92.59%> (+1.09%)`	⬆️
...m/linecorp/armeria/internal/HttpObjectEncoder.java	`58.33% <0%> (-20.84%)`	⬇️
.../armeria/common/stream/NeverInvokedSubscriber.java	`42.85% <0%> (-14.29%)`	⬇️
...armeria/server/tomcat/Tomcat90ProtocolHandler.java	`50% <0%> (-13.64%)`	⬇️
...n/java/com/linecorp/armeria/server/HttpServer.java	`40% <0%> (-10%)`	⬇️
... and 9 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 9ad1cae...02d282a. Read the comment docs.

anuraaga · 2018-04-04T16:27:22Z

core/src/main/java/com/linecorp/armeria/server/HttpServerHandler.java

@@ -197,16 +197,41 @@ public int unfinishedRequests() {
    }

    @Override
-    public void channelUnregistered(ChannelHandlerContext ctx) throws Exception {
-        super.channelUnregistered(ctx);
-        unfinishedResponses.keySet().forEach(StreamMessage::abort);


The netty documentation on these callbacks wasn't very clear, so I implemented every method and added breakpoints to try to figure it out. This was called where I expected and unregistering from armeria when unregistering from netty made intuitive sense, but if they're similar semantics seems good.

anuraaga · 2018-04-04T16:29:41Z

core/src/main/java/com/linecorp/armeria/server/HttpServerHandler.java

+            case H1C:
+            case H1:
+                // XXX(trustin): How much time is 'a little bit'?
+                ctx.channel().eventLoop().schedule(this::cleanup, 1, TimeUnit.SECONDS);


Configuring just this knob is probably overkill - setting it based on idle timeout handler might make sense, but might also be overkill.

anuraaga · 2018-04-04T16:31:23Z

core/src/main/java/com/linecorp/armeria/server/HttpServerHandler.java

        if (responseEncoder != null) {
            responseEncoder.close();
        }
+
+        unfinishedResponses.keySet().forEach(res -> {
+            if (!res.isComplete()) {


Might be mistaken but I thought our semantics allowed aborting already completed streams (since completion is asynchronous I thought it's considered best effort vs other completion events)

Yeah, it's probably redundant. Let me run the tests again without this guard tomorrow and let you know.

Everything's fine without the guard. Removed.

minwoox · 2018-04-05T04:56:33Z

core/src/main/java/com/linecorp/armeria/server/HttpResponseSubscriber.java

        cancelTimeout();
-        state = State.DONE;
+        final State state = this.state;


oldState to make it clear?

Motivation: A successfully sent response can be logged with AbortedStreamException or ClosedChannelException due to race conditions. Modifications: - Make HttpResponseSubscriber handle AbortedStreamException and ClosedChannelException better so that they are not logged unnecessarily - Make HttpServerHandler clean up unfinished HTTP/1 responses a little bit later so that they are not aborted too early. - Miscellaneous: - Fix a bug in DeferredStreamMessage where NeverInvokedSubscriber is invoked, which happens when a DeferredStreamMessage is delegated to another DeferredStreamMessage. Result: - Much less chance of redundant AbortedStreamException or ClosedChannelException

trustin · 2018-04-05T05:26:59Z

Thanks for reviewing. Will merge once CI passes.

trustin · 2018-04-05T06:56:57Z

Thank you!

Motivation: A successfully sent response can be logged with AbortedStreamException or ClosedChannelException due to race conditions. Modifications: - Make HttpResponseSubscriber handle AbortedStreamException and ClosedChannelException better so that they are not logged unnecessarily - Make HttpServerHandler clean up unfinished HTTP/1 responses a little bit later so that they are not aborted too early. - Miscellaneous: - Fix a bug in DeferredStreamMessage where NeverInvokedSubscriber is invoked, which happens when a DeferredStreamMessage is delegated to another DeferredStreamMessage. Result: - Much less chance of redundant AbortedStreamException or ClosedChannelException

trustin added the defect label Apr 4, 2018

trustin added this to the 0.61.0 milestone Apr 4, 2018

trustin requested review from anuraaga, hyangtack and minwoox April 4, 2018 15:56

trustin commented Apr 4, 2018

View reviewed changes

anuraaga approved these changes Apr 4, 2018

View reviewed changes

trustin force-pushed the fix_stream_cleanup branch from a5043bd to fa7e791 Compare April 5, 2018 01:30

hyangtack approved these changes Apr 5, 2018

View reviewed changes

minwoox reviewed Apr 5, 2018

View reviewed changes

minwoox approved these changes Apr 5, 2018

View reviewed changes

trustin force-pushed the fix_stream_cleanup branch from fa7e791 to 02d282a Compare April 5, 2018 05:25

trustin merged commit de8dfff into line:master Apr 5, 2018

trustin deleted the fix_stream_cleanup branch April 5, 2018 06:56

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve the cleanup of streaming responses #1119

Improve the cleanup of streaming responses #1119

trustin commented Apr 4, 2018

trustin Apr 4, 2018

trustin Apr 4, 2018

anuraaga Apr 4, 2018

trustin Apr 4, 2018

trustin Apr 4, 2018

trustin Apr 4, 2018

trustin Apr 4, 2018

trustin Apr 4, 2018

trustin Apr 4, 2018

trustin Apr 4, 2018 •

edited

Loading

anuraaga Apr 4, 2018

codecov bot commented Apr 4, 2018 •

edited

Loading

anuraaga Apr 4, 2018

anuraaga Apr 4, 2018

anuraaga Apr 4, 2018

trustin Apr 4, 2018 •

edited

Loading

trustin Apr 5, 2018

minwoox Apr 5, 2018

trustin Apr 5, 2018

trustin commented Apr 5, 2018

trustin commented Apr 5, 2018

Improve the cleanup of streaming responses #1119

Improve the cleanup of streaming responses #1119

Conversation

trustin commented Apr 4, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

trustin Apr 4, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov bot commented Apr 4, 2018 • edited Loading

Codecov Report

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

trustin Apr 4, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

trustin commented Apr 5, 2018

trustin commented Apr 5, 2018

trustin Apr 4, 2018 •

edited

Loading

codecov bot commented Apr 4, 2018 •

edited

Loading

trustin Apr 4, 2018 •

edited

Loading