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

Complete DefaultClientRequestContext.whenIntialized() after fully initializing a context #3636

Merged
merged 2 commits into from
Jun 18, 2021

Conversation

ikhoon
Copy link
Contributor

@ikhoon ikhoon commented Jun 15, 2021

Motivation:

LazyDynamicEndpointGroupTest.emptyEndpoint() sometimes failed in CI
builds. #3381 It expects to fail the test with EmptyEndpointException,
however, it fails with ClosedStreamException.

After digging the issue, I find out that there is a race in whenInitialized.
If the acquiredEventLoop.execute() is executed immediately and completed earlier than
returning the method,

acquiredEventLoop.execute(() -> finalWhenInitialized.complete(success));
}
return finalWhenInitialized;

the callbacks of ctx.whenInitialized() will be invoked before a RequestLog
is completed.
if (log.isComplete()) {
// Completed already; no need to send anymore.
return;
}
try {
if (!log.isAvailable(RequestLogProperty.REQUEST_CONTENT)) {
ctx.logBuilder().requestContent(GrpcLogUtil.rpcRequest(method, simpleMethodName(), message),
null);
}
final ByteBuf serialized = marshaller.serializeRequest(message);
req.write(requestFramer.writePayload(serialized));

As the req is closed already, the req.write() would be failed with
ClosedStreamException.

Modifications:

  • Complete DefaultClientRequestContext.whenIntialized() after
    initContextAndExecuteWithFallback of ClientUtil

Result:

…izing a context

Motivation:

`LazyDynamicEndpointGroupTest.emptyEndpoint()` sometimes failed in CI
builds. line#3381 It expects to fail the test with `EmptyEndpointException`,
however it fails with `ClosedStreamException`.

After digging the issue, I find out that there is a race in
`whenInitialized`.  If the `acquiredEventLoop.execute()` is
executed immediately and eailer than returning the method,
https://github.com/line/armeria/blob/d4880fe12690d2dafd2c5e7fa9f24c3b24837a00/core/src/main/java/com/linecorp/armeria/client/DefaultClientRequestContext.java#L307-L309
the callbacks of `ctx.whenInitialized()` will be invoked
before a `RequestLog` is completed.
https://github.com/line/armeria/blob/207c5e038f59802dca769936a50e219a5fe308ea/grpc/src/main/java/com/linecorp/armeria/internal/client/grpc/ArmeriaClientCall.java#L337-L348
As the `req` is closed already, the `req.write()` would
be failed with `ClosedStreamException`.

Modifications:

- Complete `DefaultClientRequestContext.whenIntialized()` after
  `initContextAndExecuteWithFallback` of `ClientUtil`

Result:

- You no longer see `ClosedStreamException` when an `EndpointGroup` is empty.
- Fixes line#3381
@ikhoon ikhoon added the defect label Jun 15, 2021
@ikhoon ikhoon added this to the 1.9.0 milestone Jun 15, 2021
@ikhoon ikhoon requested review from minwoox and trustin as code owners June 15, 2021 12:21
@codecov
Copy link

codecov bot commented Jun 15, 2021

Codecov Report

Merging #3636 (6747b57) into master (7bf1873) will increase coverage by 0.10%.
The diff coverage is 87.55%.

Impacted file tree graph

@@             Coverage Diff              @@
##             master    #3636      +/-   ##
============================================
+ Coverage     73.83%   73.94%   +0.10%     
- Complexity    14378    14530     +152     
============================================
  Files          1263     1266       +3     
  Lines         54874    55349     +475     
  Branches       7021     7103      +82     
============================================
+ Hits          40518    40929     +411     
- Misses        10786    10801      +15     
- Partials       3570     3619      +49     
Impacted Files Coverage Δ
...ava/com/linecorp/armeria/client/ClientFactory.java 65.33% <ø> (ø)
...necorp/armeria/client/DecoratingClientFactory.java 37.03% <0.00%> (-1.43%) ⬇️
.../linecorp/armeria/client/Http1ResponseDecoder.java 66.26% <0.00%> (-0.41%) ⬇️
...om/linecorp/armeria/common/ContextAwareLogger.java 4.74% <0.00%> (-0.03%) ⬇️
.../java/com/linecorp/armeria/common/HttpRequest.java 80.37% <ø> (+2.02%) ⬆️
...java/com/linecorp/armeria/common/HttpResponse.java 93.47% <ø> (-0.49%) ⬇️
...inecorp/armeria/server/AbstractBindingBuilder.java 86.27% <ø> (ø)
...java/com/linecorp/armeria/server/RouteBuilder.java 89.47% <ø> (ø)
.../linecorp/armeria/common/util/EventLoopGroups.java 42.85% <25.00%> (-2.31%) ⬇️
...com/linecorp/armeria/common/auth/OAuth1aToken.java 68.91% <70.58%> (+0.42%) ⬆️
... and 98 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 49594e9...6747b57. Read the comment docs.

Copy link
Contributor

@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.

What a brilliant!

Copy link
Member

@trustin trustin left a comment

Choose a reason for hiding this comment

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

Nice find!

Copy link
Member

@trustin trustin left a comment

Choose a reason for hiding this comment

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

Thanks, @ikhoon !

@trustin trustin merged commit 7b31b08 into line:master Jun 18, 2021
heowc pushed a commit to heowc/armeria that referenced this pull request Jun 24, 2021
…nitializing a context (line#3636)

Motivation:

`LazyDynamicEndpointGroupTest.emptyEndpoint()` sometimes failed in CI
builds. line#3381 It expects to fail the test with `EmptyEndpointException`,
however, it fails with `ClosedStreamException`.

After digging the issue, I find out that there is a race in `whenInitialized`.
If the `acquiredEventLoop.execute()` is executed immediately and completed earlier than
returning the method,
https://github.com/line/armeria/blob/d4880fe12690d2dafd2c5e7fa9f24c3b24837a00/core/src/main/java/com/linecorp/armeria/client/DefaultClientRequestContext.java#L307-L309
the callbacks of `ctx.whenInitialized()` will be invoked before a `RequestLog`
is completed.
https://github.com/line/armeria/blob/207c5e038f59802dca769936a50e219a5fe308ea/grpc/src/main/java/com/linecorp/armeria/internal/client/grpc/ArmeriaClientCall.java#L337-L348
As the `req` is closed already, the `req.write()` would be failed with
`ClosedStreamException`.

Modifications:

- Complete `DefaultClientRequestContext.whenIntialized()` after
  `initContextAndExecuteWithFallback` of `ClientUtil`

Result:

- You no longer see `ClosedStreamException` when an `EndpointGroup` is empty.
- Fixes line#3381
@ikhoon ikhoon deleted the wheninitialized-bug branch August 31, 2021 09:00
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Intermittent test failure: LazyDynamicEndpointGroupTest.emptyEndpoint()
3 participants