rpc accept loop: added backoff on logging #4974

cgbaker · 2018-12-07T20:15:59Z

adds throttling to error logging on the Accept() loop in the RPC listener, to prevent from overloading the disk in case some problem (out of file handles, out of memory) causes a tight loop

this change is also needed in memberlist

…case there is a fast fail loop (NMD-1173)

schmichael · 2018-12-07T20:22:45Z

nomad/rpc.go

+					tempDelay = max
+				}
+				r.logger.Error("failed to accept RPC conn", "error", err, "delay", tempDelay)
+				time.Sleep(tempDelay)


Technically we could also exit if the context is canceled, but with a max timeout of 1s it's not a huge deal.

select { case <-ctx.Done(): case <-time.After(tempDelay): }

good call, will do.

schmichael · 2018-12-07T20:24:41Z

nomad/rpc.go

+				}
+				r.logger.Error("failed to accept RPC conn", "error", err, "delay", tempDelay)
+				time.Sleep(tempDelay)
+			}


So the open question is: What to do for non-Temporary() errors?

We handle Temporary above fine, but we tight loop on permanent errors which seems bad. I think we exit, but that requires trusting net.Error#Temporary a lot.

net/http exits: https://github.com/golang/go/blob/master/src/net/http/server.go#L2859-L2879

Looking through the net code. It looks like a non temporary failure is fatal in all the cases I'll traced.

@schmichael Would it be possible/good idea to restart the listener? If we error at net.Listen then its pretty safe to say we're hosed and should shutdown.

@schmichael Would it be possible/good idea to restart the listener? If we error at net.Listen then its pretty safe to say we're hosed and should shutdown.

Possible? Yes, although it's not necessary for this PR or to fix the underlying issue.
Good idea? In theory yes, in practice I don't think it matters.

Ideally on permanent errors we don't spin at all and wait for a SIGHUP to hopefully change things and create new, valid listeners. In reality I'm not sure anything SIGHUP changes can impact permanent errors. They seem to mostly deal with conditions that are programming errors like trying to Accept on a non-socket FD, invalid FD, negative listen backlog, etc.

The only permanent error I even think is possible to encounter in Nomad is EINVAL because we've closed the listening socket on shutdown. We already check for the shutdown condition, so we'll never need to rely on the error check in that case.

Since as far as I know permanent errors are unreachable, I'm not too worried about how we handle them. It should never matter, but we should be conservative in our approach in case it does.

…t() errors as well (with a higher delay cap)

nickethier

Great job @cgbaker!

I've added a few comments to define some consts to get rid of the magic numbers.

nickethier · 2018-12-08T04:31:13Z

nomad/rpc.go

-			case <-ctx.Done():
-				return
-			default:
+			if tempDelay == 0 {


I think this code is just complex enough to warrant it's own r.handleAcceptErr(err) func. It looks to me we're safe to stick the tempDelay into the struct (although I think it should be renamed to be more descriptive), and do the sleep in the new func.

@nickethier , the return on r.shutdown and the continue (if we keep it) have to stay inside if the if err block, so only the sleep logic can go into handleAcceptErr. however, the r.acceptLoopDelay has to stay outside of the if block to reset the counter if err == nil, and i would be worried about the logic for acceptLoopDelay living in two places.

for example:
https://gist.github.com/cgbaker/ab90f40bcbdd97c28c057e768f39bfc9

nickethier · 2018-12-08T04:32:08Z

nomad/rpc.go

@@ -84,6 +84,7 @@ type RPCContext struct {
 // listen is used to listen for incoming RPC connections
 func (r *rpcHandler) listen(ctx context.Context) {
 	defer close(r.listenerCh)
+	var tempDelay time.Duration


I think this needs to be a more descriptive name. acceptLoopDelay or something along those lines

nickethier · 2018-12-08T04:35:58Z

nomad/rpc.go

-				return
-			default:
+			if tempDelay == 0 {
+				tempDelay = 5 * time.Millisecond


lets use a const, ex:

baseAcceptLoopDelay = 5 * time.Millisecond

nickethier · 2018-12-08T04:37:01Z

nomad/rpc.go

 			}
-
-			r.logger.Error("failed to accept RPC conn", "error", err)
+			maxDelay := 5 * time.Second


const:

maxAcceptLoopDelay = 5 * time.Second

nickethier · 2018-12-08T04:37:47Z

nomad/rpc.go

-			r.logger.Error("failed to accept RPC conn", "error", err)
+			maxDelay := 5 * time.Second
+			if ne, ok := err.(net.Error); ok && ne.Temporary() {
+				maxDelay = 1 * time.Second


const

maxAcceptLoopTemporaryDelay = 5 * time.Second

schmichael

Logic looks great. Sorry for the long road to get here. 😅

My comments are just Go idioms and style, so fixup and merge as you see fit! No blockers.

schmichael · 2018-12-12T22:48:22Z

nomad/rpc.go


 		go r.handleConn(ctx, conn, &RPCContext{Conn: conn})
 		metrics.IncrCounter([]string{"nomad", "rpc", "accept_conn"}, 1)
 	}
 }

+// Sleep to avoid spamming the log, with a maximum delay according to whether or not the error is temporary


Go has an idiom of starting method comments with the name of the method. No big deal.

Suggested change

// Sleep to avoid spamming the log, with a maximum delay according to whether or not the error is temporary

// handleAcceptErr sleeps to avoid spamming the log, with a maximum delay

// according to whether or not the error is temporary.

schmichael · 2018-12-12T22:49:40Z

nomad/rpc.go


 		go r.handleConn(ctx, conn, &RPCContext{Conn: conn})
 		metrics.IncrCounter([]string{"nomad", "rpc", "accept_conn"}, 1)
 	}
 }

+// Sleep to avoid spamming the log, with a maximum delay according to whether or not the error is temporary
+func (r *rpcHandler) handleAcceptErr(err error, ctx context.Context) {


Go has an idiom of making ctx the first argument in method calls.

schmichael · 2018-12-12T22:50:55Z

nomad/rpc.go

+func (r *rpcHandler) handleAcceptErr(err error, ctx context.Context) {
+	const baseAcceptLoopDelay = 5 * time.Millisecond
+	const maxAcceptLoopDelay = 5 * time.Second
+	const maxAcceptLoopDelayTemporaryError = 1 * time.Second


You can shorten the names since they're locals: baseDelay, maxDelay, maxDelayTempError

No need to change.

schmichael · 2018-12-12T22:52:28Z

nomad/rpc.go

-	gologger *golog.Logger
+	logger          log.Logger
+	gologger        *golog.Logger
+	acceptLoopDelay time.Duration


Define this within listen() and pass it to the error handler method unless you put it here for testing.

github-actions · 2023-02-22T02:17:24Z

I'm going to lock this pull request because it has been closed for 120 days ⏳. This helps our maintainers find and focus on the active contributions.
If you have found a problem that seems related to this change, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.

rpc accept loop: added backoff on logging for failed connections, in …

22a4bcd

…case there is a fast fail loop (NMD-1173)

cgbaker requested a review from schmichael December 7, 2018 20:16

schmichael reviewed Dec 7, 2018

View reviewed changes

Chris Baker added 2 commits December 7, 2018 22:14

nomad/rpc listener: modified to throttle logging on "permanent" Accep…

591cdb0

…t() errors as well (with a higher delay cap)

updated memberlist dependency to latest, which is missing NMD-1173 error

bbe531c

nickethier requested changes Dec 8, 2018

View reviewed changes

Chris Baker added 3 commits December 12, 2018 18:52

improved code for readability

1a34550

gofmt

44a6d9d

fixed bug in loop delay

33b9f9d

schmichael approved these changes Dec 12, 2018

View reviewed changes

some changes for more idiomatic code

3ee692c

cgbaker merged commit 5bcb24b into master Dec 13, 2018

hashicorp deleted a comment from schmichael Dec 13, 2018

github-actions bot locked as resolved and limited conversation to collaborators Feb 22, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

rpc accept loop: added backoff on logging #4974

rpc accept loop: added backoff on logging #4974

cgbaker commented Dec 7, 2018 •

edited

Loading

schmichael Dec 7, 2018

cgbaker Dec 11, 2018

schmichael Dec 7, 2018

schmichael Dec 7, 2018

nickethier Dec 8, 2018

schmichael Dec 11, 2018

nickethier left a comment

nickethier Dec 8, 2018

cgbaker Dec 11, 2018

nickethier Dec 8, 2018

nickethier Dec 8, 2018

nickethier Dec 8, 2018

nickethier Dec 8, 2018

schmichael left a comment

schmichael Dec 12, 2018

schmichael Dec 12, 2018

schmichael Dec 12, 2018

schmichael Dec 12, 2018

github-actions bot commented Feb 22, 2023

	// Sleep to avoid spamming the log, with a maximum delay according to whether or not the error is temporary
	// handleAcceptErr sleeps to avoid spamming the log, with a maximum delay
	// according to whether or not the error is temporary.

rpc accept loop: added backoff on logging #4974

rpc accept loop: added backoff on logging #4974

Conversation

cgbaker commented Dec 7, 2018 • edited Loading

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

nickethier 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

schmichael 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

github-actions bot commented Feb 22, 2023

cgbaker commented Dec 7, 2018 •

edited

Loading