2251: Fixes missing activation of the sub leg during initial endpoint discovery by iteplov · Pull Request #2268 · StackExchange/StackExchange.Redis (original) (raw)

19:07:57.0669: Connecting (sync) on .NET 6.0.9 (StackExchange.Redis: v2.6.69.61631)
19:07:57.1215: redis.api.services.revdevs.internal:6380,keepAlive=60,syncTimeout=5000,asyncTimeout=5000,allowAdmin=False,version=2.0,connectTimeout=5000,password=*****,tiebreaker=__Booksleeve_TieBreak,ssl=True,sslHost=localhost,configChannel=__Booksleeve_MasterChanged,abortConnect=False,resolveDns=False,connectRetry=3,proxy=None,configCheckSeconds=60,defaultDatabase=0
19:07:57.1273: redis.api.services.revdevs.internal:6380/Interactive: Connecting...
19:07:57.1402: redis.api.services.revdevs.internal:6380: BeginConnectAsync
'testhost.exe' (CoreCLR: clrhost): Loaded 'C:\Program Files\dotnet\shared\Microsoft.NETCore.App\6.0.9\System.Net.NameResolution.dll'. Symbol loading disabled by Include/Exclude setting.
19:07:57.1710: 1 unique nodes specified (with tiebreaker)
19:07:57.1750: redis.api.services.revdevs.internal:6380: OnConnectedAsync init (State=Connecting)
19:07:57.1783: Allowing 1 endpoint(s) 00:00:05 to respond...
19:07:57.1823: Awaiting 1 available task completion(s) for 5000ms, IOCP: (Busy=0,Free=1000,Min=12,Max=1000), WORKER: (Busy=1,Free=32766,Min=12,Max=32767), POOL: (Threads=5,QueuedItems=0,CompletedItems=6)
19:07:57.4442: TLS connection established successfully using protocol: Tls12
19:07:57.4484: redis.api.services.revdevs.internal:6380/Interactive: Connected 
19:07:57.4525: redis.api.services.revdevs.internal:6380: Server handshake
19:07:57.4549: redis.api.services.revdevs.internal:6380: Authenticating (password)
19:07:57.4757: redis.api.services.revdevs.internal:6380: Setting client name: W-ITEPLO-TJ5N7(SE.Redis-v2.6.69.61631)
19:07:57.4816: redis.api.services.revdevs.internal:6380: Auto-configuring...
19:07:57.4873: redis.api.services.revdevs.internal:6380: Requesting tie-break (Key="__Booksleeve_TieBreak")...
19:07:57.4905: redis.api.services.revdevs.internal:6380/Interactive: Writing: GET __Booksleeve_TieBreak
19:07:57.4927: redis.api.services.revdevs.internal:6380: Sending critical tracer (handshake): ECHO
19:07:57.4942: redis.api.services.revdevs.internal:6380/Interactive: Writing: ECHO
19:07:57.4958: redis.api.services.revdevs.internal:6380: Flushing outbound buffer
19:07:57.4975: redis.api.services.revdevs.internal:6380: OnEstablishingAsync complete
19:07:57.4992: redis.api.services.revdevs.internal:6380: Starting read
19:07:57.5231: redis.api.services.revdevs.internal:6380: Auto-configured (INFO) version: 6.2.6
19:07:57.5263: redis.api.services.revdevs.internal:6380: Auto-configured (INFO) server-type: cluster
19:07:57.5285: redis.api.services.revdevs.internal:6380: Auto-configured (INFO) role: primary
19:07:57.5396: Response from redis.api.services.revdevs.internal:6380/Interactive / GET __Booksleeve_TieBreak: (null)
19:07:57.5426: Response from redis.api.services.revdevs.internal:6380/Interactive / ECHO: BulkString: 16 bytes
19:07:57.5452: redis.api.services.revdevs.internal:6380: OnConnectedAsync completed (From command: ECHO)
19:07:57.5468: All 1 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=12,Max=1000), WORKER: (Busy=3,Free=32764,Min=12,Max=32767), POOL: (Threads=8,QueuedItems=0,CompletedItems=25)
19:07:57.5483: Endpoint summary:
19:07:57.5500:   redis.api.services.revdevs.internal:6380: Endpoint is ConnectedEstablished
19:07:57.5518:   redis.api.services.revdevs.internal:6380: Returned with success as Cluster primary (Source: From command: ECHO)
19:07:57.6188: services-0002-001.services.rfikkv.usw2.cache.amazonaws.com:6380: OnConnectedAsync init (State=Connecting)
19:07:57.6214: services-0001-001.services.rfikkv.usw2.cache.amazonaws.com:6380: OnConnectedAsync init (State=Connecting)
19:07:57.6240: services-0001-002.services.rfikkv.usw2.cache.amazonaws.com:6380: OnConnectedAsync init (State=Connecting)
19:07:57.6262: services-0002-002.services.rfikkv.usw2.cache.amazonaws.com:6380: OnConnectedAsync init (State=Connecting)
19:07:57.6287: Allowing 4 endpoint(s) 00:00:04.5500000 to respond...
19:07:57.6311: Awaiting 4 available task completion(s) for 4550ms, IOCP: (Busy=1,Free=999,Min=12,Max=1000), WORKER: (Busy=2,Free=32765,Min=12,Max=32767), POOL: (Threads=8,QueuedItems=0,CompletedItems=33)
19:07:57.7552: services-0001-002.services.rfikkv.usw2.cache.amazonaws.com:6380: OnConnectedAsync completed (From command: ECHO)
19:07:57.7705: services-0002-002.services.rfikkv.usw2.cache.amazonaws.com:6380: OnConnectedAsync completed (From command: ECHO)
19:07:57.8270: services-0002-001.services.rfikkv.usw2.cache.amazonaws.com:6380: OnConnectedAsync completed (From command: ECHO)
19:07:57.8316: services-0001-001.services.rfikkv.usw2.cache.amazonaws.com:6380: OnConnectedAsync completed (From command: ECHO)
19:07:57.8336: All 4 available tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=12,Max=1000), WORKER: (Busy=3,Free=32764,Min=12,Max=32767), POOL: (Threads=14,QueuedItems=0,CompletedItems=73)
19:07:57.8357: Endpoint summary:
19:07:57.8380:   services-0002-001.services.rfikkv.usw2.cache.amazonaws.com:6380: Endpoint is ConnectedEstablished
19:07:57.8399:   services-0001-001.services.rfikkv.usw2.cache.amazonaws.com:6380: Endpoint is ConnectedEstablished
19:07:57.8417:   services-0001-002.services.rfikkv.usw2.cache.amazonaws.com:6380: Endpoint is ConnectedEstablished
19:07:57.8436:   services-0002-002.services.rfikkv.usw2.cache.amazonaws.com:6380: Endpoint is ConnectedEstablished
19:07:57.8456:   services-0002-001.services.rfikkv.usw2.cache.amazonaws.com:6380: Returned with success as Cluster replica (Source: From command: ECHO)
19:07:57.8473:   services-0001-001.services.rfikkv.usw2.cache.amazonaws.com:6380: Returned with success as Cluster replica (Source: From command: ECHO)
19:07:57.8490:   services-0001-002.services.rfikkv.usw2.cache.amazonaws.com:6380: Returned with success as Cluster primary (Source: From command: ECHO)
19:07:57.8508:   services-0002-002.services.rfikkv.usw2.cache.amazonaws.com:6380: Returned with success as Cluster primary (Source: From command: ECHO)
19:07:57.8531: Cluster: 16384 of 16384 slots covered
19:07:57.8558: Endpoint Summary:
19:07:57.8590:   redis.api.services.revdevs.internal:6380: Cluster v6.2.6, primary; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
19:07:57.8629:   redis.api.services.revdevs.internal:6380: int ops=11, 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
19:07:57.8678:   redis.api.services.revdevs.internal:6380: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
19:07:57.8700:   services-0001-002.services.rfikkv.usw2.cache.amazonaws.com:6380: Cluster v6.2.6, primary; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
19:07:57.8720:   services-0001-002.services.rfikkv.usw2.cache.amazonaws.com:6380: int ops=10, 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
19:07:57.8740:   services-0001-002.services.rfikkv.usw2.cache.amazonaws.com:6380: Circular op-count snapshot; int: 0+10=10 (1.00 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
19:07:57.8761:   services-0002-002.services.rfikkv.usw2.cache.amazonaws.com:6380: Cluster v6.2.6, primary; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
19:07:57.8787:   services-0002-002.services.rfikkv.usw2.cache.amazonaws.com:6380: int ops=10, 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
19:07:57.8809:   services-0002-002.services.rfikkv.usw2.cache.amazonaws.com:6380: Circular op-count snapshot; int: 0+10=10 (1.00 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
19:07:57.8832:   services-0002-001.services.rfikkv.usw2.cache.amazonaws.com:6380: Cluster v6.2.6, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
19:07:57.8856:   services-0002-001.services.rfikkv.usw2.cache.amazonaws.com:6380: int ops=11, 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
19:07:57.8889:   services-0002-001.services.rfikkv.usw2.cache.amazonaws.com:6380: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
19:07:57.8918:   services-0001-001.services.rfikkv.usw2.cache.amazonaws.com:6380: Cluster v6.2.6, replica; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
19:07:57.8937:   services-0001-001.services.rfikkv.usw2.cache.amazonaws.com:6380: int ops=11, 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
19:07:57.8957:   services-0001-001.services.rfikkv.usw2.cache.amazonaws.com:6380: Circular op-count snapshot; int: 0+11=11 (1.10 ops/s; spans 10s); sub: 0+4=4 (0.40 ops/s; spans 10s)
19:07:57.8983: Sync timeouts: 0; async timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
19:07:57.9006: Starting heartbeat...
19:07:57.9043: Total connect time: 837 ms