Fixes "messages get sent out-of-order when a backlog is created by another thread" by TimLovellSmith · Pull Request #1779 · StackExchange/StackExchange.Redis (original) (raw)
Hm. Only one test failure on appveyor, and seems like it could just be not enough worker threads again?
22:26:40.679: Awaiting 2 available task completion(s) for 5000ms, IOCP: (Busy=1,Free=999,Min=4,Max=1000), WORKER: (Busy=5,Free=2042,Min=4,Max=2047)
22:26:40.679: Response from Interactive/127.0.0.1:6379 / PING: SimpleString: PONG
22:26:45.699: Not all available tasks completed cleanly (from ReconfigureAsync#1747, timeout 5000ms), IOCP: (Busy=0,Free=1000,Min=4,Max=1000), WORKER: (Busy=5,Free=2042,Min=4,Max=2047)
dotnet : [xUnit.net 00:00:07.99] MultiMaster.TestMultiWithTiebreak(a: null, b: "127.0.0.1:6381", elected: "127.0.0.1:6381") [FAIL]
Skipped TestInfoReplicationChecks.Exec [1 ms]
Failed MultiMaster.TestMultiWithTiebreak(a: null, b: "127.0.0.1:6381", elected: "127.0.0.1:6381") [5 s]
Error Message:
elected
Expected: True
Actual: False
Stack Trace:
at StackExchange.Redis.Tests.MultiMaster.TestMultiWithTiebreak(String a, String b, String elected) in C:\projects\stackexchange-redis\tests\StackExchange.Redis.Tests\MultiMaster.cs:line 79
Standard Output Messages:
Running under .NET Framework 4.8.4121.0 (4.0.30319.42000)
Running on: Microsoft Windows 10.0.17763
22:26:40.663: 127.0.0.1:6379,127.0.0.1:6381,name=TestMultiWithTiebreak,password=*****,tiebreaker=__tie__
22:26:40.663: 127.0.0.1:6379/Interactive: Connecting...
22:26:40.663: 127.0.0.1:6379: BeginConnectAsync
22:26:40.663: 127.0.0.1:6379/Interactive: Connected
22:26:40.663: 127.0.0.1:6379: Server handshake
22:26:40.663: 127.0.0.1:6379: Authenticating (password)
22:26:40.663: 127.0.0.1:6379: Setting client name: TestMultiWithTiebreak
22:26:40.663: 127.0.0.1:6379: Auto-configuring...
22:26:40.663: 127.0.0.1:6379: Sending critical tracer (handshake): ECHO
22:26:40.663: 127.0.0.1:6379/Interactive: Writing: ECHO
22:26:40.663: 127.0.0.1:6379: Flushing outbound buffer
22:26:40.663: 127.0.0.1:6379: OnEstablishingAsync complete
22:26:40.663: 127.0.0.1:6379: Starting read
22:26:40.663: 127.0.0.1:6379: Auto-configured (CONFIG) read-only replica: true
22:26:40.663: 127.0.0.1:6379: Auto-configured (CONFIG) databases: 2000
22:26:40.663: 127.0.0.1:6381/Interactive: Connecting...
22:26:40.663: 127.0.0.1:6379: Auto-configured (INFO) version: 3.0.503
22:26:40.663: 127.0.0.1:6379: Auto-configured (INFO) server-type: standalone
22:26:40.663: 127.0.0.1:6381: BeginConnectAsync
22:26:40.663: 127.0.0.1:6379: Auto-configured (INFO) role: master
22:26:40.663: Response from Interactive/127.0.0.1:6379 / ECHO: BulkString: 16 bytes
22:26:40.679: 127.0.0.1:6381/Interactive: Connected
22:26:40.679: 127.0.0.1:6381: Server handshake
22:26:40.679: 127.0.0.1:6381: Authenticating (password)
22:26:40.679: 127.0.0.1:6381: Setting client name: TestMultiWithTiebreak
22:26:40.679: 127.0.0.1:6381: Auto-configuring...
22:26:40.679: 127.0.0.1:6381: Sending critical tracer (handshake): ECHO
22:26:40.679: 127.0.0.1:6381/Interactive: Writing: ECHO
22:26:40.679: 127.0.0.1:6381: Flushing outbound buffer
22:26:40.679: 127.0.0.1:6381: OnEstablishingAsync complete
22:26:40.679: 127.0.0.1:6381: Starting read
22:26:40.679: 127.0.0.1:6381: Auto-configured (CONFIG) read-only replica: true
22:26:40.679: 127.0.0.1:6381: Auto-configured (CONFIG) databases: 2000
22:26:40.679: 127.0.0.1:6381: Auto-configured (INFO) version: 3.0.503
22:26:40.679: 127.0.0.1:6381: Auto-configured (INFO) server-type: standalone
22:26:40.679: 127.0.0.1:6381: Auto-configured (INFO) role: master
22:26:40.679: Response from Interactive/127.0.0.1:6381 / ECHO: BulkString: 16 bytes
22:26:40.679: 2 unique nodes specified
22:26:40.679: 127.0.0.1:6379: OnConnectedAsync init (State=ConnectedEstablished)
22:26:40.679: 127.0.0.1:6379: OnConnectedAsync completed (already connected start)
22:26:40.679: 127.0.0.1:6379/Interactive: Writing: PING
22:26:40.679: 127.0.0.1:6381: OnConnectedAsync init (State=ConnectedEstablished)
22:26:40.679: 127.0.0.1:6381: OnConnectedAsync completed (already connected start)
22:26:40.679: 127.0.0.1:6381/Interactive: Writing: PING
22:26:40.679: Response from Interactive/127.0.0.1:6381 / PING: SimpleString: PONG
22:26:40.679: 127.0.0.1:6381: OnConnectedAsync completed (already connected end)
22:26:40.679: Allowing 2 endpoint(s) 00:00:05 to respond...
22:26:40.679: Awaiting 2 available task completion(s) for 5000ms, IOCP: (Busy=1,Free=999,Min=4,Max=1000), WORKER: (Busy=5,Free=2042,Min=4,Max=2047)
22:26:40.679: Response from Interactive/127.0.0.1:6379 / PING: SimpleString: PONG
22:26:45.699: Not all available tasks completed cleanly (from ReconfigureAsync#1747, timeout 5000ms), IOCP: (Busy=0,Free=1000,Min=4,Max=1000), WORKER: (Busy=5,Free=2042,Min=4,Max=2047)
22:26:45.699: Task[0] Status: WaitingForActivation
22:26:45.699: Task[1] Status: RanToCompletion
22:26:45.699: 127.0.0.1:6379: Endpoint is ConnectedEstablished
22:26:45.699: 127.0.0.1:6381: Endpoint is ConnectedEstablished
22:26:45.699: 127.0.0.1:6379: Requesting tie-break (Key="__tie__")...
22:26:45.699: 127.0.0.1:6379/Interactive: Writing: GET __tie__
22:26:45.699: 127.0.0.1:6381: Requesting tie-break (Key="__tie__")...
22:26:45.699: 127.0.0.1:6381/Interactive: Writing: GET __tie__
22:26:45.699: 127.0.0.1:6379: Did not respond
22:26:45.699: 127.0.0.1:6381: Returned with success as Standalone primary (Source: Already connected)
22:26:45.699: Waiting for tiebreakers...
22:26:45.699: Awaiting 2 tiebreaker task completion(s) for 50ms, IOCP: (Busy=0,Free=1000,Min=4,Max=1000), WORKER: (Busy=5,Free=2042,Min=4,Max=2047)
22:26:45.699: Response from Interactive/127.0.0.1:6379 / GET __tie__: (null)
22:26:45.699: Response from Interactive/127.0.0.1:6381 / GET __tie__: BulkString: 14 bytes
22:26:45.699: All 2 tiebreaker tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=4,Max=1000), WORKER: (Busy=5,Free=2042,Min=4,Max=2047)
22:26:45.699: Election: 127.0.0.1:6379 had no tiebreaker set
22:26:45.699: Election: 127.0.0.1:6381 nominates: 127.0.0.1:6381
22:26:45.699: Election: Single master detected: 127.0.0.1:6381
22:26:45.699: 127.0.0.1:6381: Clearing as RedundantMaster
22:26:45.699: 127.0.0.1:6379: Standalone v3.0.503, master; 2000 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active; not in use: DidNotRespond
22:26:45.699: 127.0.0.1:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=4, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
22:26:45.699: 127.0.0.1:6379: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
22:26:45.699: 127.0.0.1:6381: Standalone v3.0.503, master; 2000 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
22:26:45.699: 127.0.0.1:6381: int ops=12, qu=0, qs=0, qc=0, wr=0, socks=1; sub ops=4, qu=0, qs=0, qc=0, wr=0, subs=1, socks=1
22:26:45.699: 127.0.0.1:6381: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
22:26:45.699: Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
22:26:45.699: Starting heartbeat...
22:26:45.699: 22:26:45.699: Connect took: 5028ms
22:26:45.715: Service Counts: (Scheduler) Queue: 2897, Pool: 0