From 2fca40d5b1699aafa940fcf6260a994ca8a7567f Mon Sep 17 00:00:00 2001 From: David Eads Date: Tue, 10 Nov 2020 14:52:36 -0500 Subject: [PATCH] put a message, not a stack, in the log on a timeout --- .../apiserver/pkg/server/filters/timeout_test.go | 12 ++++++++++-- .../k8s.io/apiserver/pkg/server/filters/wrap.go | 16 ++++++++++------ 2 files changed, 20 insertions(+), 8 deletions(-) diff --git a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go index 53b3cfb9ac7e..15767fec6383 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/timeout_test.go @@ -244,8 +244,12 @@ func TestErrConnKilled(t *testing.T) { t.Fatal("expected to receive an error") } + // we should only get one line for this, not the big stack from before capturedOutput := readStdErr() - if len(capturedOutput) > 0 { + if strings.Count(capturedOutput, "\n") != 1 { + t.Errorf("unexpected output captured actual = %v", capturedOutput) + } + if !strings.Contains(capturedOutput, `timeout or abort while handling: GET "/"`) { t.Errorf("unexpected output captured actual = %v", capturedOutput) } } @@ -330,8 +334,12 @@ func TestErrConnKilledHTTP2(t *testing.T) { t.Fatal("expected to receive an error") } + // we should only get one line for this, not the big stack from before capturedOutput := readStdErr() - if len(capturedOutput) > 0 { + if strings.Count(capturedOutput, "\n") != 1 { + t.Errorf("unexpected output captured actual = %v", capturedOutput) + } + if !strings.Contains(capturedOutput, `timeout or abort while handling: GET "/"`) { t.Errorf("unexpected output captured actual = %v", capturedOutput) } diff --git a/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go b/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go index 569f9fdb22ab..34c5398dba98 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go +++ b/staging/src/k8s.io/apiserver/pkg/server/filters/wrap.go @@ -17,13 +17,14 @@ limitations under the License. package filters import ( - "k8s.io/apiserver/pkg/endpoints/request" - "k8s.io/klog/v2" + "fmt" "net/http" "k8s.io/apimachinery/pkg/util/runtime" "k8s.io/apiserver/pkg/endpoints/metrics" + "k8s.io/apiserver/pkg/endpoints/request" "k8s.io/apiserver/pkg/server/httplog" + "k8s.io/klog/v2" ) // WithPanicRecovery wraps an http Handler to recover and log panics (except in the special case of http.ErrAbortHandler panics, which suppress logging). @@ -42,12 +43,15 @@ func WithPanicRecovery(handler http.Handler, resolver request.RequestInfoResolve // // Note that the ReallyCrash variable controls the behaviour of the HandleCrash function // So it might actually crash, after calling the handlers - info, err := resolver.NewRequestInfo(req) - if err != nil { + if info, err := resolver.NewRequestInfo(req); err != nil { metrics.RecordRequestAbort(req, nil) - return + } else { + metrics.RecordRequestAbort(req, info) } - metrics.RecordRequestAbort(req, info) + // This call can have different handlers, but the default chain rate limits. Call it after the metrics are updated + // in case the rate limit delays it. If you outrun the rate for this one timed out requests, something has gone + // seriously wrong with your server, but generally having a logging signal for timeouts is useful. + runtime.HandleError(fmt.Errorf("timeout or abort while handling: %v %q", req.Method, req.URL.Path)) return } http.Error(w, "This request caused apiserver to panic. Look in the logs for details.", http.StatusInternalServerError)