Skip to content

census: Fix retry stats data race (v2)#8459

Merged
dapengzhang0 merged 5 commits into
grpc:masterfrom
dapengzhang0:fix-retry-race
Sep 2, 2021
Merged

census: Fix retry stats data race (v2)#8459
dapengzhang0 merged 5 commits into
grpc:masterfrom
dapengzhang0:fix-retry-race

Conversation

@dapengzhang0

Copy link
Copy Markdown
Contributor

(This is a modified version of #8422 using a lock for synchronization.)

There is data race in CensusStatsModule. CallAttemptsTracerFactory:

If client call is cancelled while an active stream on the transport is not committed, then a noop substream will be committed and the active stream will be cancelled. Because the active stream cancellation triggers the stream listener closed() on the transport thread, the closed() method can be invoked concurrently with the call listener onClose(). Therefore, one CallAttemptsTracerFactory.attemptEnded() can be called concurrently with CallAttemptsTracerFactory.callEnded(), and there could be data race on RETRY_DELAY_PER_CALL. See also the regression test added.

The same data race can happen in hedging case when one of hedges is committed and completes the call, other uncommitted hedges would cancel themselves and trigger their stream listeners closed() on the transport_thread concurrently.

Fixing the race by recording RETRY_DELAY_PER_CALL once both the conditions are met:

  • callEnded is true
  • number of active streams is 0.

this.status = status;
boolean shouldRecordFinishedCall = false;
synchronized (lock) {
if (callEnded) {

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

How could this be true?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

It's not possible unless there's some bug like #7921.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Then how about we log a warning if it happens? An assert would be great, but I don't think we are that confident. A warning with "this is a bug" at least would mean we'd learn if it happens. If it does trigger, it seems it'd probably be at a low rate.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Added logging.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

Uhh... if we think it can happen, then let's just have the notice of the bug here and return like you had.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Do you mean to include the link to the issue in the log?

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

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

No, I mean delete the log statement. I was suggesting the log statement only if we thought it wasn't possible but it would be worrisome to add an assert. If we think it is possible, just having a comment seems good.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Done.

Comment thread census/src/main/java/io/grpc/census/CensusStatsModule.java
@dapengzhang0
dapengzhang0 merged commit 2faa748 into grpc:master Sep 2, 2021
@dapengzhang0
dapengzhang0 deleted the fix-retry-race branch September 2, 2021 17:24
@dapengzhang0 dapengzhang0 added the TODO:backport PR needs to be backported. Removed after backport complete label Sep 2, 2021
dapengzhang0 added a commit to dapengzhang0/grpc-java that referenced this pull request Sep 2, 2021
There is data race in `CensusStatsModule. CallAttemptsTracerFactory`:

If client call is cancelled while an active stream on the transport is not committed, then a [noop substream](https://github.com/grpc/grpc-java/blob/v1.40.0/core/src/main/java/io/grpc/internal/RetriableStream.java#L486) will be committed and the active stream will be cancelled. Because the active stream cancellation triggers the stream listener closed() on the _transport_ thread, the closed() method can be invoked concurrently with the call listener onClose(). Therefore, one `CallAttemptsTracerFactory.attemptEnded()` can be called concurrently with `CallAttemptsTracerFactory.callEnded()`, and there could be data race on RETRY_DELAY_PER_CALL. See also the regression test added.

The same data race can happen in hedging case when one of hedges is committed and completes the call, other uncommitted hedges would cancel themselves and trigger their stream listeners closed() on the transport_thread concurrently. 

Fixing the race by recording RETRY_DELAY_PER_CALL once both the conditions are met: 
- callEnded is true 
- number of active streams is 0.
dapengzhang0 added a commit that referenced this pull request Sep 2, 2021
There is data race in `CensusStatsModule. CallAttemptsTracerFactory`:

If client call is cancelled while an active stream on the transport is not committed, then a [noop substream](https://github.com/grpc/grpc-java/blob/v1.40.0/core/src/main/java/io/grpc/internal/RetriableStream.java#L486) will be committed and the active stream will be cancelled. Because the active stream cancellation triggers the stream listener closed() on the _transport_ thread, the closed() method can be invoked concurrently with the call listener onClose(). Therefore, one `CallAttemptsTracerFactory.attemptEnded()` can be called concurrently with `CallAttemptsTracerFactory.callEnded()`, and there could be data race on RETRY_DELAY_PER_CALL. See also the regression test added.

The same data race can happen in hedging case when one of hedges is committed and completes the call, other uncommitted hedges would cancel themselves and trigger their stream listeners closed() on the transport_thread concurrently. 

Fixing the race by recording RETRY_DELAY_PER_CALL once both the conditions are met: 
- callEnded is true 
- number of active streams is 0.
@ejona86 ejona86 removed the TODO:backport PR needs to be backported. Removed after backport complete label Sep 8, 2021
@github-actions github-actions Bot locked as resolved and limited conversation to collaborators Dec 8, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants