dotnet/Nerdbank.Streams

Unstable test: MultiplexingStreamTests.CancelChannelOfferBeforeAcceptance

Closed this issue · 1 comments

In this build, the test failed with this log:

2018-10-16T20:27:23.8679970Z Failed   MultiplexingStreamTests.CancelChannelOfferBeforeAcceptance(cancelFirst: False)
2018-10-16T20:27:23.8682090Z Error Message:
2018-10-16T20:27:23.8682500Z  System.InvalidOperationException : Channel is no longer available for acceptance.
2018-10-16T20:27:23.8682620Z Stack Trace:
2018-10-16T20:27:23.8682820Z    at Nerdbank.Streams.MultiplexingStream.AcceptChannelOrThrow(Channel channel, ChannelOptions options) in /Users/vsts/agent/2.140.2/work/1/s/src/Nerdbank.Streams/MultiplexingStream.cs:line 803
2018-10-16T20:27:23.8682980Z    at Nerdbank.Streams.MultiplexingStream.AcceptChannelAsync(String name, ChannelOptions options, CancellationToken cancellationToken) in /Users/vsts/agent/2.140.2/work/1/s/src/Nerdbank.Streams/MultiplexingStream.cs:line 469
2018-10-16T20:27:23.8683200Z    at MultiplexingStreamTests.CancelChannelOfferBeforeAcceptance(Boolean cancelFirst) in /Users/vsts/agent/2.140.2/work/1/s/src/Nerdbank.Streams.Tests/MultiplexingStreamTests.cs:line 377
2018-10-16T20:27:23.8684250Z --- End of stack trace from previous location where exception was thrown ---
2018-10-16T20:27:23.8684460Z Standard Output Messages:
2018-10-16T20:27:23.8684550Z  mx2 Information: 0 : Multiplexing protocol established successfully.
2018-10-16T20:27:23.8684700Z  mx1 Information: 0 : Multiplexing protocol established successfully.
2018-10-16T20:27:23.8685170Z  mx1 Information: 12 : Sending Offer frame for channel 2, carrying 0 bytes of content.
2018-10-16T20:27:23.8685330Z  mx2 Information: 13 : Received Offer frame for channel 2 with 0 bytes of content.
2018-10-16T20:27:23.8685410Z  mx2 Information: 9 : Remote party offers channel 2 "" which has no pending AcceptChannelAsync
2018-10-16T20:27:23.8685550Z  mx1 Information: 11 : Offer of channel 2 ("") canceled.
2018-10-16T20:27:23.8685630Z  mx1 Information: 10 : Local channel "" stream disposed.
2018-10-16T20:27:23.8685760Z  mx1 Information: 12 : Sending ChannelTerminated frame for channel 2, carrying 0 bytes of content.
2018-10-16T20:27:23.8685850Z  mx2 Information: 13 : Received ChannelTerminated frame for channel 2 with 0 bytes of content.
2018-10-16T20:27:23.8685930Z  mx2 Information: 7 : Accepting channel 2 "" which is already offered by the other side.
2018-10-16T20:27:23.8686100Z  mx2 Information: 10 : Local channel "" stream disposed.
2018-10-16T20:27:23.8686170Z  mx2 Information: 12 : Sending ChannelTerminated frame for channel 2, carrying 0 bytes of content.
2018-10-16T20:27:23.8686340Z  mx1 Information: 13 : Received ChannelTerminated frame for channel 2 with 0 bytes of content.
2018-10-16T20:27:23.8686410Z  mx1 Information: 5 : Disposing.
2018-10-16T20:27:23.8686540Z  mx2 Information: 5 : Disposing.

This is indeed a timing bug in the library. When we're in the lock, we choose which channel offer to accept. Then we exit the lock, and throw if we can't accept it. But between exiting the lock and accepting the offer, another thread has received notice that the offer is canceled, and disposes the channel. Then the original accepting thread throws because it can't accept the channel it has chosen.