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

@@ -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:

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)
+}

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."