proxy: add handling for subprocess cleanup, retries #311

skabbes · 2017-09-06T09:41:58Z

As a result of #308, I spent quite a long time debugging up + my application code.

In the end there were errors in both places, for up - I tried to fix and prevent this debugging session from anyone in the future.

A network error was assumed to be a process crash, which is not always the case (this was actually causing lambda to run out of file descriptors for processes in this case)
A 'bad route' would backoff and retry forever
listen_timeout can guard against nonsense usage (longer than 30 seconds, when 30 seconds is the APIGateway limit).
unused function basic in internal/proxy/request.go

It seems that most of these have already been identified as issues, TODOS, so likely nothing surprising here. I know that I didn't follow the normal "discuss features before implementing them", so feel free to throw all this code away if you like.

Implementation Strategy
When the child http server encounters an error, asynchronously ensure it is cleanly shut down by sending a nice SIGINT followed by a SIGKILL after 10 seconds of non-response. This shutdown process is done in parallel with setting up a new child server (on a separate goroutine) in order to allow the proxy to serve traffic as fast as possible. However in order to prevent slow shutdowns from causing resource exhaustion like in #308 we make the channel blocking with N=3. In addition, I tried to add sufficient logging to help future developers debug and understand this in the future.

Known Bugs
none

Notable Omissions

Even though process shutdown is aysnc from the http serving code, it is still serialized (failing processes aren't cleaned up concurrently with each other)
SIGKILL delay is not configurable (naming suggestion: shutdown_timeout?). This would be particularly helpful in tests, since I have added a 10 second test :(
A failed child process cannot be recognized until another request is made.
Clean shutdown of relay.Proxy (and cleanup goroutine)
Concurrent execution: The whole proxy class is serialized on the ServeHTTP entry point, since lambda operates this way anyway - I don't see a strong reason to layer this complexity in until a FaaS adds actual concurrent execution.

skabbes

Adding some self comments to try to direct the review.

skabbes · 2017-09-06T09:42:31Z

config/relay.go

@@ -30,6 +31,11 @@ func (r *Relay) Default() error {
 		r.ListenTimeout = 15
 	}

+	if r.ListenTimeout >= 30 {
+		err := fmt.Errorf("listen_timeout should be less 30s (APIGateway integration limit)")
+		return errors.Wrap(err, ".listen_timeout")


Not sure the vision here, but it did feel a little dirty to assume APIGateway in this part of the code.

We could move that to a Validate() method in ./config/lambda.go, I suppose we should give it a little breathing room to ensure the error surfaces, API GW-level timeouts are a bit more annoying to troubleshoot

I didn't realize API GW's was so low, would definitely be nice to cap lambda.timeout to that as well.

Hmm, I couldn't really find a great way to accomplish that without an import cycle. I went ahead and made Relay aware of what platform it is deployed on, so that it can validate itself based on that.

skabbes · 2017-09-06T09:43:00Z

http/relay/relay.go

 // TODO: add timeout
 // TODO: scope all plugin logs to their plugin name
 // TODO: utilize BufferPool
-// TODO: if the first Start() fails then bail


This one was already done as far as I could tell. relay.New implements this.

skabbes · 2017-09-06T09:43:43Z

http/relay/relay.go

 	}

 	if err := p.Start(); err != nil {
 		return nil, err
 	}

+	// Launch a goroutine for cleaning up the old commands as they are abandoned
+	go p.cleanupAbandoned()


To stay lightweight, we could also launch this on demand.

skabbes · 2017-09-06T09:45:30Z

http/relay/relay.go

+	}
+
+	p.port = port
+	p.target = target


I was trying to keep the property that if we return an error, p is not mutated.

tightened this up even more.

just kidding, this caused a pretty bad bug - reverting.

skabbes · 2017-09-06T09:46:58Z

http/relay/relay.go

+		case <-time.After(10 * time.Second):
+			ctx.Warnf("proxy (pid=%d) sending SIGKILL", cmd.Process.Pid)
+			cmd.Process.Kill()
+			<-waitDone


No matter what, we have to wait for the Wait to return, otherwise we don't know if the resources were atually released.

skabbes · 2017-09-06T09:51:47Z

http/relay/relay_test.go

-	t.Run("GET simple", func(t *testing.T) {
+	// newRequestBody is a helper to fetch the body from a child process route
+	newRequestBody := func(t *testing.T, method, path string, body io.Reader) string {
+		t.Helper()


Not sure if you're aware, but if you use this and have failing tests - t.Helper() tells go to skip this stack frame for error reporting line numbers and use the parent stack frame. VERY helpful for knowing which tests actually failed.

nice! yea I had read about it in the release notes but I haven't tried it

skabbes · 2017-09-06T09:53:25Z

http/relay/relay_test.go

+	t.Run("child process cleanup", func(t *testing.T) {
+
+		// In this test, we test that a child process who stops accepting network connections
+		// (but hasn't crashed) is gracefully asked to be shut down


This is effectively the test case that I was running into in prod, up-proxy thought my process failed (because of a network error), however in actuality it didn't. Therefore the process stayed around forever, and continued to use resource on the lambda container.

skabbes · 2017-09-06T09:59:14Z

http/relay/relay_test.go

+		})
+
+		// In this test, we test that a child process who swallows the "nice" shutdown signal
+		// will eventually be sent a SIGKILL and shut down


I think this is a nice thing up can do, if your clean shutdown isn't working. I think all Lambda processes need to be kill-9 safe anyway

skabbes · 2017-09-06T09:59:52Z

internal/proxy/request.go

-
-	pair := strings.SplitN(string(b), ":", 2)
-	return pair[0], pair[1], nil
-}


skabbes · 2017-09-06T10:01:44Z

http/relay/testdata/basic/app.js

+
+let server;
+
+const routes = {};


refactored this without adding deps, it was getting complex.

added:

/env to fetch a key from process.env

/close to stop accepting connections without killing the server

/pid to fetch the pid

/swallowSignals to install signal handlers

tj · 2017-09-06T15:58:35Z

woah awesome! Should be able to get to this today

tj

cool LGTM! thanks for digging into this, I don't see any issues, I'll pull it down and test it out.

the additional timeout option sounds good to me too

tj · 2017-09-06T20:47:17Z

config/relay.go

@@ -30,6 +31,11 @@ func (r *Relay) Default() error {
 		r.ListenTimeout = 15
 	}

+	if r.ListenTimeout >= 30 {
+		err := fmt.Errorf("listen_timeout should be less 30s (APIGateway integration limit)")
+		return errors.Wrap(err, ".listen_timeout")


We could move that to a Validate() method in ./config/lambda.go, I suppose we should give it a little breathing room to ensure the error surfaces, API GW-level timeouts are a bit more annoying to troubleshoot

I didn't realize API GW's was so low, would definitely be nice to cap lambda.timeout to that as well.

tj · 2017-09-06T20:52:13Z

http/relay/relay.go

 	b := p.config.Proxy.Backoff.Backoff()

+	retries := 0


I think b has b.Attempts we could utilize for this

I also defaulted maxRetries to be config.Proxy.Backoff.Attmpets.

tj · 2017-09-06T20:56:24Z

http/relay/relay.go

+	}
+
+	p.port = port
+	p.target = target


skabbes

Ok, I think this is ready for re-review.

tj · 2017-09-10T19:52:22Z

did you have any issues running the tests from root? oddly they work every time in http/relay, but fail every time from root haha checking it out

tj · 2017-09-10T19:55:04Z

nvm, seems to be that gt program, go test works fine

tj · 2017-09-10T19:57:38Z

awesome 💥 , big thanks man!

skabbes added 5 commits September 6, 2017 01:42

config: give a nice error message for nonsense listen_timeout

09c4ae2

lint: remove unused function

84daf5d

proxy: add maxRetries to consistently failing endpoints

c043a29

proxy: add process cleanup for abandoned proxy child processes

864799f

test: test proxy child process cleanup

6ba6355

skabbes commented Sep 6, 2017

View reviewed changes

lint: try to make codeclimate happy?

472b02f

tj requested changes Sep 6, 2017

View reviewed changes

docs: document and configure shutdown_timeout feature

d70f89b

skabbes commented Sep 6, 2017

View reviewed changes

skabbes added 2 commits September 6, 2017 16:40

hotfix: fix small regression after code review refactor

f3f94f7

test: fix tests after refactoring

446b42a

tj closed this in badf351 Sep 10, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

proxy: add handling for subprocess cleanup, retries #311

proxy: add handling for subprocess cleanup, retries #311

skabbes commented Sep 6, 2017

skabbes left a comment

skabbes Sep 6, 2017

tj Sep 6, 2017

skabbes Sep 6, 2017

skabbes Sep 6, 2017

skabbes Sep 6, 2017

skabbes Sep 6, 2017

tj Sep 6, 2017 •

edited

skabbes Sep 6, 2017

skabbes Sep 6, 2017

skabbes Sep 6, 2017

skabbes Sep 6, 2017

tj Sep 10, 2017

skabbes Sep 6, 2017

skabbes Sep 6, 2017

skabbes Sep 6, 2017

skabbes Sep 6, 2017

tj commented Sep 6, 2017

tj left a comment

tj Sep 6, 2017

tj Sep 6, 2017

skabbes Sep 6, 2017

tj Sep 6, 2017 •

edited

skabbes left a comment

tj commented Sep 10, 2017 •

edited

tj commented Sep 10, 2017

tj commented Sep 10, 2017

proxy: add handling for subprocess cleanup, retries #311

proxy: add handling for subprocess cleanup, retries #311

Conversation

skabbes commented Sep 6, 2017

skabbes 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

tj Sep 6, 2017 • 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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tj commented Sep 6, 2017

tj 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

tj Sep 6, 2017 • edited

Choose a reason for hiding this comment

skabbes left a comment

Choose a reason for hiding this comment

tj commented Sep 10, 2017 • edited

tj commented Sep 10, 2017

tj commented Sep 10, 2017

tj Sep 6, 2017 •

edited

tj Sep 6, 2017 •

edited

tj commented Sep 10, 2017 •

edited