Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

2251: Fixes missing activation of the sub leg during initial endpoint discovery #2268

Merged
merged 5 commits into from
Oct 15, 2022

Conversation

iteplov
Copy link
Contributor

@iteplov iteplov commented Oct 12, 2022

Allegedly fixes #2251 and #2265 but likely introduces all kinds of regressions.

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

@iteplov iteplov changed the title 2251: fixes missing activation of the sub leg during initial endpoint… 2251: fixes missing activation of the sub leg during initial endpoint discovery Oct 12, 2022
Comment on lines 6 to 7
<TargetFrameworks>net461;netstandard2.0;net472;netcoreapp3.1;net5.0</TargetFrameworks>
<!-- <TargetFrameworks>net461;netstandard2.0;net472;netcoreapp3.1;net5.0</TargetFrameworks> -->
<TargetFrameworks>netstandard2.0;net472;netcoreapp3.1;net5.0</TargetFrameworks>
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

was too lazy to install net461

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FWIW, you don't have to install it to build for it - packages pull it in via NuGet :)

Copy link
Collaborator

@NickCraver NickCraver left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry I was down a few days here but this is spot on - added some tests around the cases it happens to prevent regressions and detect what's happening. Also tweaked the logging to show a bit more.

@NickCraver NickCraver changed the title 2251: fixes missing activation of the sub leg during initial endpoint discovery 2251: Fixes missing activation of the sub leg during initial endpoint discovery Oct 15, 2022
@NickCraver NickCraver merged commit 85c1b2b into StackExchange:main Oct 15, 2022
@NickCraver
Copy link
Collaborator

@iteplov Thank you for this! Hugely appreciated time saver <3

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
2 participants