Unstable test: MultiplexingStreamTests.CancelChannelOfferBeforeAcceptance
Closed this issue · 1 comments
AArnott commented
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.
AArnott commented
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.