Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Publish stream events before calling RequestLogBuilder #2832

Merged
merged 5 commits into from Jun 26, 2020

Conversation

trustin
Copy link
Member

@trustin trustin commented Jun 24, 2020

Motivation:

We currently call RequestLogBuilder methods even before publishing
stream events (StreamMesssage.write/close/abort()) in some places,
such as HttpResponseDecoder. This can be a problem because the
callbacks added to the RequestLog may be invoked even before any
stream events are published.

For example, HttpResponseDecoder may fail to publish the received
ResponseHeaders when a RequestLog callback aborts the response
even before the publication, leading to the following exception:

io.netty.handler.codec.http2.Http2Exception: failed to consume a HEADERS frame
    at io.netty.handler.codec.http2.Http2Exception.connectionError(Http2Exception.java:117)
    at com.linecorp.armeria.client.Http2ResponseDecoder.onHeadersRead(Http2ResponseDecoder.java:206)
    at com.linecorp.armeria.client.Http2ResponseDecoder.onHeadersRead(Http2ResponseDecoder.java:219)
    ...
Caused by: com.linecorp.armeria.common.stream.ClosedStreamException: null
    at com.linecorp.armeria.common.stream.ClosedStreamException.get(ClosedStreamException.java:37)
    at com.linecorp.armeria.common.stream.StreamWriter.write(StreamWriter.java:72)
    at com.linecorp.armeria.client.Http2ResponseDecoder.onHeadersRead(Http2ResponseDecoder.java:203)
    ... 40 common frames omitted

Modifications:

  • Add a generalized mechanism to defer any RequestLogProperty:
    • isDeferred(RequestLogProperty)
    • defer(RequestLogProperty)
    • defer*Content*() and isDefer*Content*Set() have been deprecated.
  • Defer setting some log properties before publishing stream events,
    so that they are recorded after the publication.
  • Miscellaneous:
    • Do not warn unnecessarily when propagating content previews in
      DefaultRequestLog.propagate*().
    • Make HttpClientMaxConcurrentStreamTest.exceededMaxStreamsPropagatesFailureCorrectly()
      less flaky.
    • Optimize DefaultRequestLog.isAvailable()

Result:

Motivation:

We currently call `RequestLogBuilder` methods even before publishing
stream events (`StreamMesssage.write/close/abort()`) in some places,
such as `HttpResponseDecoder`. This can be a problem because the
callbacks added to the `RequestLog` may be invoked even before any
stream events are published.

For example, `HttpResponseDecoder` may fail to publish the received
`ResponseHeaders` when a `RequestLog` callback aborts the response
even before the publication, leading to the following exception:

    io.netty.handler.codec.http2.Http2Exception: failed to consume a HEADERS frame
        at io.netty.handler.codec.http2.Http2Exception.connectionError(Http2Exception.java:117)
        at com.linecorp.armeria.client.Http2ResponseDecoder.onHeadersRead(Http2ResponseDecoder.java:206)
        at com.linecorp.armeria.client.Http2ResponseDecoder.onHeadersRead(Http2ResponseDecoder.java:219)
        ...
    Caused by: com.linecorp.armeria.common.stream.ClosedStreamException: null
        at com.linecorp.armeria.common.stream.ClosedStreamException.get(ClosedStreamException.java:37)
        at com.linecorp.armeria.common.stream.StreamWriter.write(StreamWriter.java:72)
        at com.linecorp.armeria.client.Http2ResponseDecoder.onHeadersRead(Http2ResponseDecoder.java:203)
        ... 40 common frames omitted

Modifications:

- Add a generalized mechanism to defer any `RequestLogProperty`:
  - `isDeferred(RequestLogProperty)`
  - `defer(RequestLogProperty)`
  - `defer*Content*()` and `isDefer*Content*Set()` have been deprecated.
- Defer setting some log properties before publishing stream events,
  so that they are recorded after the publication.
- Miscellaneous:
  - Do not warn unnecessarily when propagating content previews in
    `DefaultRequestLog.propagate*()`.
  - Make `HttpClientMaxConcurrentStreamTest.exceededMaxStreamsPropagatesFailureCorrectly()`
    less flaky.
  - Optimize `DefaultRequestLog.isAvailable()`

Result:

- No more `Http2Exception: failed to consume a HEADERS frame` error.
- No more `You tried to set the content preview twice` warning.
  - Fixes line#2830
- (Deprecation) `RequestLogBuilder.defer*Content*()` and
  `isDefer*Content*Set()` have been deprecated in favor of
  `defer(RequestLogProperty)` and `isDeferred(RequestLogProperty)`.
final HttpRequest req = request();
if (req != null) {
autoFillSchemeAndAuthority();
req.abort(cause);
req.abort(wrapped);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure why it was cause before. 🤔

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It seems my mistake. 😱

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it didn't do any harm anyways. 😆
First appeared at: https://github.com/line/armeria/pull/2248/files#diff-d437ddb5e0b4572dba776949bacf9becR233

@codecov
Copy link

codecov bot commented Jun 24, 2020

Codecov Report

Merging #2832 into master will decrease coverage by 0.10%.
The diff coverage is 67.45%.

Impacted file tree graph

@@             Coverage Diff              @@
##             master    #2832      +/-   ##
============================================
- Coverage     72.79%   72.69%   -0.11%     
+ Complexity    12055    12039      -16     
============================================
  Files          1069     1068       -1     
  Lines         46848    46881      +33     
  Branches       5866     5868       +2     
============================================
- Hits          34105    34081      -24     
- Misses         9736     9793      +57     
  Partials       3007     3007              
Impacted Files Coverage Δ Complexity Δ
...m/linecorp/armeria/server/thrift/THttpService.java 73.30% <12.50%> (-2.12%) 52.00 <1.00> (-1.00)
...p/armeria/client/retry/AbstractRetryingClient.java 80.57% <50.00%> (ø) 32.00 <0.00> (ø)
...corp/armeria/common/logging/DefaultRequestLog.java 75.82% <58.42%> (-2.24%) 225.00 <18.00> (-3.00)
...corp/armeria/common/logging/RequestLogBuilder.java 71.42% <66.66%> (-28.58%) 5.00 <4.00> (+4.00) ⬇️
...m/linecorp/armeria/client/HttpResponseDecoder.java 87.75% <90.00%> (+1.42%) 21.00 <0.00> (ø)
...rp/armeria/client/DefaultClientRequestContext.java 93.43% <100.00%> (ø) 76.00 <0.00> (ø)
...om/linecorp/armeria/client/HttpClientDelegate.java 100.00% <100.00%> (ø) 30.00 <0.00> (ø)
...rmeria/client/logging/ContentPreviewingClient.java 86.66% <100.00%> (ø) 6.00 <0.00> (ø)
.../linecorp/armeria/client/retry/RetryingClient.java 85.27% <100.00%> (ø) 42.00 <2.00> (ø)
...necorp/armeria/client/retry/RetryingRpcClient.java 78.94% <100.00%> (ø) 18.00 <1.00> (ø)
... and 32 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 e0e1b91...27fda46. Read the comment docs.

Copy link
Member

@minwoox minwoox left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you!

requireNonNull(properties, "properties");
final int flags = interestedFlags(properties);
checkArgument(flags != 0, "properties is empty.");
return isAvailable(flags);
}

private boolean isAvailable(int interestedFlags) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: can remove this method and just call hasInterestedFlags directly?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I guess it's better keeping it for readability - isAvailable(interestedFlags) vs. hasInterestedFlags(this.flags, interestedFlags).

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

SGTM. 😄

warnedSettingContentPreviewTwice = true;
logger.warn("You tried to set the content preview twice: {} " +
logger.warn("You tried to set the response content preview twice: {} " +
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, I needed it.

Copy link
Contributor

@ikhoon ikhoon left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks! @trustin

if (!isDeferRequestContentSet() ||
(isDeferRequestContentSet() && isAvailable(RequestLogProperty.REQUEST_CONTENT))) {
if (!hasInterestedFlags(deferredFlags, RequestLogProperty.REQUEST_CONTENT) ||
isAvailable(RequestLogProperty.REQUEST_CONTENT)) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

@trustin trustin merged commit 3447983 into line:master Jun 26, 2020
@trustin trustin deleted the log_after_publication branch June 26, 2020 09:25
fmguerreiro pushed a commit to fmguerreiro/armeria that referenced this pull request Sep 19, 2020
Motivation:

We currently call `RequestLogBuilder` methods even before publishing
stream events (`StreamMesssage.write/close/abort()`) in some places,
such as `HttpResponseDecoder`. This can be a problem because the
callbacks added to the `RequestLog` may be invoked even before any
stream events are published.

For example, `HttpResponseDecoder` may fail to publish the received
`ResponseHeaders` when a `RequestLog` callback aborts the response
even before the publication, leading to the following exception:

    io.netty.handler.codec.http2.Http2Exception: failed to consume a HEADERS frame
        at io.netty.handler.codec.http2.Http2Exception.connectionError(Http2Exception.java:117)
        at com.linecorp.armeria.client.Http2ResponseDecoder.onHeadersRead(Http2ResponseDecoder.java:206)
        at com.linecorp.armeria.client.Http2ResponseDecoder.onHeadersRead(Http2ResponseDecoder.java:219)
        ...
    Caused by: com.linecorp.armeria.common.stream.ClosedStreamException: null
        at com.linecorp.armeria.common.stream.ClosedStreamException.get(ClosedStreamException.java:37)
        at com.linecorp.armeria.common.stream.StreamWriter.write(StreamWriter.java:72)
        at com.linecorp.armeria.client.Http2ResponseDecoder.onHeadersRead(Http2ResponseDecoder.java:203)
        ... 40 common frames omitted

Modifications:

- Add a generalized mechanism to defer any `RequestLogProperty`:
  - `isDeferred(RequestLogProperty)`
  - `defer(RequestLogProperty)`
  - `defer*Content*()` and `isDefer*Content*Set()` have been deprecated.
- Defer setting some log properties before publishing stream events,
  so that they are recorded after the publication.
- Miscellaneous:
  - Do not warn unnecessarily when propagating content previews in
    `DefaultRequestLog.propagate*()`.
  - Make `HttpClientMaxConcurrentStreamTest.exceededMaxStreamsPropagatesFailureCorrectly()`
    less flaky.
  - Optimize `DefaultRequestLog.isAvailable()`

Result:

- No more `Http2Exception: failed to consume a HEADERS frame` error.
- No more `You tried to set the content preview twice` warning.
  - Fixes line#2830
- Slightly faster `RequestLogAccess.isAvailable()` implementation.
- (Deprecation) `RequestLogBuilder.defer*Content*()` and
  `isDefer*Content*Set()` have been deprecated in favor of
  `defer(RequestLogProperty)` and `isDeferred(RequestLogProperty)`.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

'You tried to set the content preview twice' warning on a client with one preview decorator
4 participants