From 71b587b58e16d9822388fc843e8c65238f5b8b23 Mon Sep 17 00:00:00 2001 From: Ta-Ching Chen Date: Sat, 28 Sep 2019 14:22:20 +0800 Subject: [PATCH] Use ErrorHandler to handle proxy error (#1310) The router prints error no matter what error type it is. It's useful for troubleshooting, however, it also prints the context canceled error, which means that users abort request before reply and its really normal nowadays. Also, the router returns 502 if error is not nil and may confused client if it's a timeout error. To solve these problems, this PR adds an error handler to reverse proxy to examine the return error and change the status code when needed. --- pkg/router/functionHandler.go | 38 +++++++++++++++-- pkg/router/functionHandler_test.go | 25 ++++++++++++ test/tests/test_function_timeout.sh | 63 +++++++++++++++++++++++++++++ 3 files changed, 123 insertions(+), 3 deletions(-) create mode 100755 test/tests/test_function_timeout.sh diff --git a/pkg/router/functionHandler.go b/pkg/router/functionHandler.go index 978548ba..1bf6c68b 100644 --- a/pkg/router/functionHandler.go +++ b/pkg/router/functionHandler.go @@ -296,12 +296,18 @@ func (roundTripper RetryingRoundTripper) RoundTrip(req *http.Request) (*http.Res if roundTripper.timeout <= 0 { roundTripper.timeout = fv1.DEFAULT_FUNCTION_TIMEOUT } - roundTripper.logger.Debug("Creating context for request for ", zap.Any("Time", roundTripper.timeout)) - ctx, closeCtx := context.WithTimeout(context.Background(), time.Duration(roundTripper.timeout)*time.Second) + + roundTripper.logger.Debug("Creating context for request for ", zap.Any("time", roundTripper.timeout)) + // pass request context as parent context for the case + // that user aborts connection before timeout. Otherwise, + // the request won't be canceled until the deadline exceeded + // which may be a potential security issue. + ctx, closeCtx := context.WithTimeout(req.Context(), time.Duration(roundTripper.timeout)*time.Second) // forward the request to the function service resp, err = ocRoundTripper.RoundTrip(req.WithContext(ctx)) closeCtx() + if err == nil { // Track metrics httpMetricLabels.code = resp.StatusCode @@ -348,7 +354,6 @@ func (roundTripper RetryingRoundTripper) RoundTrip(req *http.Request) (*http.Res // if transport.RoundTrip returns a non-network dial error (e.g. "context canceled"), then relay it back to user if !isNetDialErr { - err = errors.Wrapf(err, "error sending request to function %v", fnMeta.Name) return resp, err } @@ -459,6 +464,7 @@ func (fh functionHandler) handler(responseWriter http.ResponseWriter, request *h funcHandler: &fh, timeout: timeout, }, + ErrorHandler: getProxyErrorHandler(fh.logger, fh.function), } proxy.ServeHTTP(responseWriter, request) @@ -499,6 +505,32 @@ func getCanaryBackend(fnMetadatamap map[string]*metav1.ObjectMeta, fnWtDistribut return fnMetadatamap[fnName] } +// getProxyErrorHandler returns a reverse proxy error handler +func getProxyErrorHandler(logger *zap.Logger, fnMeta *metav1.ObjectMeta) func(rw http.ResponseWriter, req *http.Request, err error) { + return func(rw http.ResponseWriter, req *http.Request, err error) { + status := http.StatusBadGateway + switch err { + case context.Canceled: + // 499 CLIENT CLOSED REQUEST + // A non-standard status code introduced by nginx for the case + // when a client closes the connection while nginx is processing the request. + // Reference: https://httpstatuses.com/499 + status = 499 + logger.Debug("client closes the connection", + zap.Any("function", fnMeta), zap.Any("request_header", req.Header)) + case context.DeadlineExceeded: + status = http.StatusGatewayTimeout + logger.Error("function not responses before the timeout", + zap.Any("function", fnMeta), zap.Any("request_header", req.Header)) + default: + logger.Error("error sending request to function", + zap.Error(err), zap.Any("function", fnMeta), zap.Any("request_header", req.Header)) + } + // TODO: return error message that contains traceable UUID back to user. Issue #693 + rw.WriteHeader(status) + } +} + // addForwardedHostHeader add "forwarded host" to request header func (roundTripper RetryingRoundTripper) addForwardedHostHeader(req *http.Request) { // for more detailed information, please visit: diff --git a/pkg/router/functionHandler_test.go b/pkg/router/functionHandler_test.go index 0a6a4933..9826e634 100644 --- a/pkg/router/functionHandler_test.go +++ b/pkg/router/functionHandler_test.go @@ -17,6 +17,8 @@ limitations under the License. package router import ( + "context" + "errors" "log" "net/http" "net/http/httptest" @@ -24,6 +26,7 @@ import ( "testing" "time" + "github.com/stretchr/testify/assert" "go.uber.org/zap" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -90,3 +93,25 @@ func TestFunctionProxying(t *testing.T) { testRequest(fhURL, testResponseString) } + +func TestProxyErrorHandler(t *testing.T) { + logger, err := zap.NewDevelopment() + assert.Nil(t, err) + errHandler := getProxyErrorHandler(logger, nil) + + req, err := http.NewRequest("GET", "http://foobar.com", nil) + assert.Nil(t, err) + + req.Header.Set("foo", "bar") + respRecorder := httptest.NewRecorder() + errHandler(respRecorder, req, context.Canceled) + assert.Equal(t, 499, respRecorder.Code) + + respRecorder = httptest.NewRecorder() + errHandler(respRecorder, req, context.DeadlineExceeded) + assert.Equal(t, http.StatusGatewayTimeout, respRecorder.Code) + + respRecorder = httptest.NewRecorder() + errHandler(respRecorder, req, errors.New("dummy")) + assert.Equal(t, http.StatusBadGateway, respRecorder.Code) +} diff --git a/test/tests/test_function_timeout.sh b/test/tests/test_function_timeout.sh new file mode 100755 index 00000000..f5a89b38 --- /dev/null +++ b/test/tests/test_function_timeout.sh @@ -0,0 +1,63 @@ +#!/bin/bash + +set -euo pipefail +source $(dirname $0)/../utils.sh + +TEST_ID=$(generate_test_id) +echo "TEST_ID = $TEST_ID" + +tmp_dir="/tmp/test-$TEST_ID" +mkdir -p $tmp_dir + +ROOT=$(dirname $0)/../.. + +env=nodejs-$TEST_ID +fn=nodejs-hello-$TEST_ID + +export FISSION_ROUTER=localhost:8888 + +cleanup() { + log "Cleaning up..." + clean_resource_by_id $TEST_ID + rm -rf $tmp_dir +} + +if [ -z "${TEST_NOCLEANUP:-}" ]; then + trap cleanup EXIT +else + log "TEST_NOCLEANUP is set; not cleaning up test artifacts afterwards." +fi + +# Create a function in nodejs, test it with an HTTP trigger. +# Update it and check it's output, the output should be +# different from the previous one. + +log "Creating nodejs env" +fission env create --name $env --image $NODE_RUNTIME_IMAGE + +log "Creating function" +echo 'function sleep(e){return new Promise(t=>{setTimeout(t,e)})}module.exports=async function(e){return await sleep(5000),{status:200,body:"hello, world!\n"}};' > $tmp_dir/foo.js +fission fn create --name $fn --env $env --code $tmp_dir/foo.js --fntimeout 10 + +log "Creating route" +fission route create --function $fn --url /$fn --method GET + +log "Waiting for router to catch up" +sleep 10 + +log "Checking for valid response" +timeout 60 bash -c "test_fn $fn 'hello, world!'" + +log "Updating function timeout setting" +fission fn update --name $fn --fntimeout 2 + +log "Waiting for router to update cache" +sleep 10 + +log "Doing an HTTP GET on the function's route" +response=$(curl -s -o /dev/null -w "%{http_code}" http://$FISSION_ROUTER/$fn) + +log "Checking for status code" +echo $response | grep -i 504 + +log "All done."