resolver: improve signaling for missing account lookups #4151

wallyqs · 2023-05-11T22:14:02Z

When using the account resolver and a JWT is not found, the client could often get an i/o timeout error due to not receiving a timely response before the account resolver fetch request times out. In this PR, instead of waiting for the fetch request to timeout, a resolver without JWTs will notify as well that it could not find a matching JWT, waiting for a response from all servers ~~but with a delay to let resolver that do have the JWT to respond first~~.

Also included in this PR is some cleanup to the logs emitted by the resolver.

Tests added
Branch rebased on top of current main (git pull --rebase origin main)
Changes squashed to a single commit (described here)
Build is green in Travis CI
You have certified that the contribution is your original work and that you license the work to the project under the Apache 2 license

derekcollison · 2023-05-11T23:18:23Z

server/accounts.go

 	dr.DirJWTStore.changed = func(pubKey string) {
 		if v, ok := s.accounts.Load(pubKey); ok {
 			if theJwt, err := dr.LoadAcc(pubKey); err != nil {
-				s.Errorf("update got error on load: %v", err)
+				s.Errorf("RESOLVER - Update got error on load: %v", err)


Do we have cases where we all caps things similar? Maybe DirResolver?

I used all caps so that it would look similar to SYSTEM logs, but I will update to DirResolver instead which would be clearer

Updated to DirResolver to label these instead, logs now look like this: https://gist.github.com/wallyqs/9c968143014f2e5fb61b7d99ec0f5326

server/accounts.go

derekcollison · 2023-05-13T00:30:07Z

server/accounts.go

+		if theJWT, err := dr.DirJWTStore.LoadAcc(accName); err != nil {
+			if errors.Is(err, fs.ErrNotExist) {
+				s.Debugf("DirResolver - Could not find account %q", accName)
+				go func() {


So wondering if this should be a concern. I know why you are putting it into a separate go routine because of the sleep, but this could cause of an explosion of Go routines yes?

Like if we did a tight loop of clients trying to connect with a bad account we would be spinning these in every server for every lookup request no?

Maybe what we do for this version of the server, is wait for all servers if we receive a nil response. This way we can send a nil response immediately but on the receiving side we see the nil so wait for more responses. We know how many other servers are in the system internally so we can know when we are done.

sounds good, I will explore this idea and update. I was concerned about blocking but would now prefer to be cautious with spinning to many go routines here.

Maybe do a quick debug.PrintStack() there too to see if we are rooted in a route or GW read..

If we are we can not block for sure, but this approach might work.

I think that approach will work much better and can get faster responses for the happy path when servers online, I updated with this new heuristic.

Signed-off-by: Waldemar Quevedo <wally@nats.io>

Also update logs based on comments Signed-off-by: Waldemar Quevedo <wally@nats.io>

Signed-off-by: Waldemar Quevedo <wally@nats.io>

derekcollison

Some comments, we are close.

server/accounts.go

derekcollison

Some comments, we are close.

Signed-off-by: Waldemar Quevedo <wally@nats.io>

derekcollison · 2023-05-13T16:08:51Z

server/accounts.go

+	// Resolver will wait for available routes + gateways to reply
+	// before serving an error in case there weren't any found.
+	expectedServers := len(s.routes)
+	if s.gateway != nil {


I think this is always non nil IIRC.

Yes, instead the test could be:

if s.gateway.enabled { ..

There is currently no API to get the number of remotes, you could add one, but otherwise you should lock:

s.gateway.RLock() expectedServers += len(s.gateway.remotes) s.gateway.RUnlock()

Could use s.sys.servers

Switched to use s.sys.servers to use the detected active servers instead.

derekcollison · 2023-05-13T16:10:13Z

server/accounts.go

@@ -4223,24 +4233,39 @@ func (s *Server) fetch(res AccountResolver, name string, timeout time.Duration)
 	respC := make(chan []byte, 1)
 	accountLookupRequest := fmt.Sprintf(accLookupReqSubj, name)
 	s.mu.Lock()
+	// Resolver will wait for available routes + gateways to reply
+	// before serving an error in case there weren't any found.
+	expectedServers := len(s.routes)


The server maps all other servers in a different data struct when it received remote statsz updates etc.
Could use that since if this is an expanded supercluster with leafnodes sharing system accounts this will not account for that.

To keep in mind when merging to dev, one then should use s.numRoutes() because it accounts for pooled routes, per-account, etc...

Using s.sys.servers instead for the check now.

derekcollison · 2023-05-13T16:11:37Z

server/accounts.go

 	if s.sys == nil || s.sys.replies == nil {
 		s.mu.Unlock()
 		return _EMPTY_, fmt.Errorf("eventing shut down")
 	}
 	replySubj := s.newRespInbox()
 	replies := s.sys.replies
+
 	// Store our handler.
 	replies[replySubj] = func(sub *subscription, _ *client, _ *Account, subject, _ string, msg []byte) {
 		clone := make([]byte, len(msg))


Should we check for the nil responses here?

var clone []byte if len(msg) > 0 { }

Added this check to do the copy when not empty.

Signed-off-by: Waldemar Quevedo <wally@nats.io>

server/accounts.go

derekcollison · 2023-05-14T16:47:54Z

server/accounts.go

-		clone := make([]byte, len(msg))
-		copy(clone, msg)
+		var clone []byte
+		var isEmpty bool


You can just set this directly..

isEmpty := len(msg)

Signed-off-by: Waldemar Quevedo <wally@nats.io>

derekcollison

LGTM

When using the nats account resolver and a JWT is not found, the client could often get an i/o timeout error due to not receiving a timely response before the account resolver fetch request times out. Now instead of waiting for the fetch request to timeout, a resolver without JWTs will notify as well that it could not find a matching JWT, waiting for a response from all active servers. Also included in this PR is some cleanup to the logs emitted by the resolver. Signed-off-by: Waldemar Quevedo <wally@nats.io>

wallyqs marked this pull request as ready for review May 11, 2023 22:14

wallyqs requested a review from a team as a code owner May 11, 2023 22:14

wallyqs requested a review from derekcollison May 11, 2023 22:34

derekcollison reviewed May 11, 2023

View reviewed changes

wallyqs force-pushed the jwt-resolver-bad-creds branch from 6dcdd7e to f58d3d0 Compare May 12, 2023 23:26

derekcollison self-requested a review May 13, 2023 00:26

derekcollison requested changes May 13, 2023

View reviewed changes

wallyqs added 3 commits May 12, 2023 21:27

resolver: improve signaling for missing account lookups

11915f4

Signed-off-by: Waldemar Quevedo <wally@nats.io>

Update not found delay to be 1/10th of fetch timeout

811ef75

Also update logs based on comments Signed-off-by: Waldemar Quevedo <wally@nats.io>

resolver: wait for all available servers to respond on fetch

94b8d0b

Signed-off-by: Waldemar Quevedo <wally@nats.io>

wallyqs force-pushed the jwt-resolver-bad-creds branch from 3c0ee93 to 94b8d0b Compare May 13, 2023 04:27

derekcollison self-requested a review May 13, 2023 04:54

derekcollison reviewed May 13, 2023

View reviewed changes

server/accounts.go Outdated Show resolved Hide resolved

server/accounts.go Show resolved Hide resolved

server/accounts.go Outdated Show resolved Hide resolved

derekcollison reviewed May 13, 2023

View reviewed changes

review updates

13db582

Signed-off-by: Waldemar Quevedo <wally@nats.io>

wallyqs force-pushed the jwt-resolver-bad-creds branch from 0c3144a to 13db582 Compare May 13, 2023 07:11

derekcollison self-requested a review May 13, 2023 16:07

derekcollison reviewed May 13, 2023

View reviewed changes

use detected active servers when waiting for acc lookup

9198044

Signed-off-by: Waldemar Quevedo <wally@nats.io>

derekcollison reviewed May 14, 2023

View reviewed changes

review updates

4af3ded

Signed-off-by: Waldemar Quevedo <wally@nats.io>

derekcollison self-requested a review May 14, 2023 17:27

derekcollison approved these changes May 14, 2023

View reviewed changes

wallyqs merged commit 3c4ed54 into main May 14, 2023
2 checks passed

wallyqs deleted the jwt-resolver-bad-creds branch May 14, 2023 18:10

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

resolver: improve signaling for missing account lookups #4151

resolver: improve signaling for missing account lookups #4151

wallyqs commented May 11, 2023 •

edited

derekcollison May 11, 2023

wallyqs May 12, 2023

wallyqs May 12, 2023

derekcollison May 13, 2023

derekcollison May 13, 2023

wallyqs May 13, 2023

derekcollison May 13, 2023

wallyqs May 13, 2023

derekcollison left a comment

derekcollison left a comment

derekcollison May 13, 2023

kozlovic May 14, 2023

derekcollison May 14, 2023

wallyqs May 14, 2023

derekcollison May 13, 2023

kozlovic May 14, 2023

wallyqs May 14, 2023

derekcollison May 13, 2023

wallyqs May 14, 2023

derekcollison May 14, 2023

derekcollison left a comment

resolver: improve signaling for missing account lookups #4151

resolver: improve signaling for missing account lookups #4151

Conversation

wallyqs commented May 11, 2023 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

derekcollison left a comment

Choose a reason for hiding this comment

derekcollison left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

derekcollison left a comment

Choose a reason for hiding this comment

wallyqs commented May 11, 2023 •

edited