Logical bug related to the reordering issue - SendTracer PING in tiebreak happens before AUTH (original) (raw)
From the call today, Nick and I feel this code has a logical problem that it doesn't actually wait to send the tracer ( available[i] = server.SendTracer(log);) until after the connection is authenticated, which was why the ordering bugfix broke tests.
Repro branch:
repro1759
Test scenario:
C:\repo\StackExchange.Redis>dotnet test ".\Build.csproj" -c Release --no-build --logger trx --filter TestMultiWithTiebreak
ConnectionMultiplexer.ReconfigureAsync
for (int i = 0; i < available.Length; i++)
{
Trace("Testing: " + Format.ToString(endpoints[i]));
var server = GetServerEndPoint(endpoints[i]);
//server.ReportNextFailure();
servers[i] = server;
if (reconfigureAll && server.IsConnected)
{
log?.WriteLine($"Refreshing {Format.ToString(server.EndPoint)}...");
// note that these will be processed synchronously *BEFORE* the tracer is processed,
// so we know that the configuration will be up to date if we see the tracer
server.AutoConfigure(null);
}
log?.WriteLine($"Server endpoint {server.EndPoint} is in {server.ConnectionState}");
available[i] = server.SendTracer(log);
if (useTieBreakers)
{
log?.WriteLine($"Requesting tie-break from {Format.ToString(server.EndPoint)} > {RawConfig.TieBreaker}...");
Message msg = Message.Create(0, flags, RedisCommand.GET, tieBreakerKey);
msg.SetInternalCall();
msg = LoggingMessage.Create(log, msg);
tieBreakers[i] = server.WriteDirectAsync(msg, ResultProcessor.String);
}
}
Failed MultiMaster.TestMultiWithTiebreak(a: null, b: "127.0.0.1:6381", elected: "127.0.0.1:6381") [51 ms]
Error Message:
failed to nominate
Expected: False
Actual: True
Stack Trace:
at StackExchange.Redis.Tests.MultiMaster.TestMultiWithTiebreak(String a, String b, String elected) in C:\repo\StackExchange.Redis\tests\StackExchange.Redis.Tests\MultiMaster.cs:line 77
Standard Output Messages:
Running under .NET Core 3.1.15 (3.1.15)
Running on: Microsoft Windows 10.0.19043
17:01:26.485: 17:01:26.485: Connect took: 14ms
17:01:26.487: 127.0.0.1:6379,127.0.0.1:6381,name=TestMultiWithTiebreak,password=*****,tiebreaker=tie
Connecting 127.0.0.1:6379/Interactive...
BeginConnect: 127.0.0.1:6379
Connected Interactive/127.0.0.1:6379
Server handshake
Authenticating (password) to endpoint 127.0.0.1:6379
Setting client name: TestMultiWithTiebreak
Auto-configure...
Connecting 127.0.0.1:6381/Interactive...
BeginConnect: 127.0.0.1:6381
Sending critical tracer message ECHO: Interactive/127.0.0.1:6379
Writing to Interactive/127.0.0.1:6379: ECHO
Flushing outbound buffer
Starting read
Connected Interactive/127.0.0.1:6381
Server handshake
Authenticating (password) to endpoint 127.0.0.1:6381
Setting client name: TestMultiWithTiebreak
Auto-configure...
Sending critical tracer message ECHO: Interactive/127.0.0.1:6381
Writing to Interactive/127.0.0.1:6381: ECHO
Flushing outbound buffer
Starting read
2 unique nodes specified
Server endpoint 127.0.0.1:6379 is in ConnectedEstablishing
Requesting tie-break from 127.0.0.1:6379 > tie...
Server endpoint 127.0.0.1:6381 is in Connecting
Requesting tie-break from 127.0.0.1:6381 > tie...
Allowing endpoints 00:00:05 to respond...
Awaiting task completion, IOCP: (Busy=2,Free=998,Min=8,Max=1000), WORKER: (Busy=4,Free=32763,Min=8,Max=32767)
Writing to Interactive/127.0.0.1:6381: PING
Writing to Interactive/127.0.0.1:6381: GET tie
Response from Interactive/127.0.0.1:6381 / ECHO: BulkString: 16 bytes
Response from Interactive/127.0.0.1:6379 / ECHO: BulkString: 16 bytes
Writing to Interactive/127.0.0.1:6379: PING
Writing to Interactive/127.0.0.1:6379: GET tie
Response from Interactive/127.0.0.1:6379 / PING: SimpleString: PONG
Response from Interactive/127.0.0.1:6379 / GET tie: (null)
Finished awaiting tasks, IOCP: (Busy=0,Free=1000,Min=8,Max=1000), WORKER: (Busy=5,Free=32762,Min=8,Max=32767)
127.0.0.1:6379 returned with success
127.0.0.1:6381 faulted: AuthenticationFailure (None, last-recv: 690) on 127.0.0.1:6381/Interactive, Idle/ComputeResult, last: ECHO, origin: SetResult, outstanding: 13, last-read: 0s ago, last-write: 0s ago, unanswered-write: 0s ago, keep-alive: 60s, state: ConnectedEstablishing, mgr: 8 of 10 available, last-heartbeat: never, global: 0s ago, v: 2.2.44.26105