Repository: kubernetes
Issue: APIserver logs status code 200 instead of 500 for serialization errors
Labels: kind/bug,sig/api-machinery,priority/important-longterm,lifecycle/frozen

<!-- Please use this template while reporting a bug and provide as much info as possible. Not doing so may result in your bug not being addressed in a timely manner. Thanks!

If the matter is security related, please disclose it privately via https://kubernetes.io/security/
-->


**What happened**:
I submitted a request with a serialization error [(error location)](https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go#L103)

The APIServer logged a 200 for the request even though the request had a serialization error and is a 500 elsewhere in the apiserver code:
```
E0401 12:41:54.216095  172135 writers.go:176] apiserver was unable to write a JSON response: aaron-prindle-injected-1: tcp broken
E0401 12:41:54.216128  172135 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"aaron-prindle-injected-1: tcp broken"}
I0401 12:41:54.217262  172135 wrap.go:47] GET /api/v1/pods?timeout=100ms: (2.162959ms) 200 [podlist-error/v0.0.0 (linux/amd64) kubernetes/$Format [::1]:44860]
```
full logs here: https://gist.github.com/aaron-prindle/4eb47176263fb449a350343f44ed885d

**What you expected to happen**:
I expected the APIServer to log this request as a 500, possibly with some stack information.

**How to reproduce it (as minimally and precisely as possible)**:
Submit a request with a serialization error  [(error location)](https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go#L103).  Then view the apiserver logs.  I was able to reproducibly hit this error by using this code snippet in [writers.go:103-105](https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go#L103-L105) along with with a specific timeout on my requests for identification:
```
	err := encoder.Encode(object, w)
	if req.URL.String() == "/api/v1/pods?timeout=100ms" {
		err = fmt.Errorf("aaron-prindle-injected-1: tcp broken")
	}
	if err != nil {
		errSerializationFatal(err, encoder, w)
	}
```

**Anything else we need to know?**:
I was able to track down this issue to [timeout.go:200-202](https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go#L200-L202).  It appears that timeout.go is masking the 500 here, 500 is being [passed in](https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go#L196) but for some reason (still having trouble understanding where it is set) tw.wroteHeader is true which is causing the timeout handler to not update the header with a 500 and log the 200.  If I remove either of the wroteHeader= true lines, [timeout.go:179](https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go#L179) or [timeout.go:204 ](https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go#L204) I still see the error.  Only when both of those sets are removed does the apiserver correctly log a 500.  A simple change that appears to work without modifying the wroteHeader logic is to change [timeout.go:200](https://github.com/kubernetes/kubernetes/blob/master/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go#L200) to 
```
if tw.timedOut || (tw.wroteHeader && code != http.StatusInternalServerError) || tw.hijacked) {
```
Logs with this change:
```
E0401 13:00:54.347310  180356 writers.go:176] apiserver was unable to write a JSON response: aaron-prindle-injected-1: tcp broken
E0401 13:00:54.347337  180356 status.go:71] apiserver received an error that is not an metav1.Status: &errors.errorString{s:"aaron-prindle-injected-1: tcp broken"}
I0401 13:00:54.348675  180356 wrap.go:47] GET /api/v1/pods?timeout=100ms: (2.953008ms) 500
goroutine 10036 [running]:
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/httplog.(*respLogger).recordStatus(0xc0002156c0, 0x1f4)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:208 +0xc8
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/httplog.(*respLogger).WriteHeader(0xc0002156c0, 0x1f4)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/httplog/httplog.go:187 +0x35
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/filters.(*baseTimeoutWriter).WriteHeader(0xc004105460, 0x1f4)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/filters/timeout.go:227 +0x9b
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/metrics.(*ResponseWriterDelegator).WriteHeader(0xc005996570, 0x1f4)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go:365 +0x45
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters.httpResponseWriterWithInit.Write(0x0, 0x5ac9bda, 0x10, 0x1f4, 0x8f2d3c0, 0xc00224f668, 0xc004b327e0, 0x81, 0x81, 0xc00074aa80, ...)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go:51 +0x1ba
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters.errSerializationFatal(0x8e9c420, 0xc0059e0cb0, 0x7f678ceef5e8, 0xc007fd7290, 0x0, 0x5ac9bda, 0x10, 0x1f4, 0x8f2d3c0, 0xc00224f668)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go:192 +0x1ce
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters.SerializeObject(0x5ac9bda, 0x10, 0x7f678ceef5e8, 0xc007fd7290, 0x8f2d3c0, 0xc00224f668, 0xc008e4d800, 0xc8, 0x8eb4740, 0xc000215a40)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go:125 +0x1d4
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters.WriteObjectNegotiated(0x8f318c0, 0xc00128d860, 0x0, 0x0, 0x5aa1355, 0x2, 0x8f2d3c0, 0xc00224f668, 0xc008e4d800, 0xc8, ...)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go:150 +0x3d7
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters.WriteObject(0xc8, 0x0, 0x0, 0x5aa1355, 0x2, 0x8f318c0, 0xc00128d860, 0x8eb4740, 0xc000215a40, 0x8f2d3c0, ...)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go:72 +0x2b5
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers.transformResponseObject(0x8f415c0, 0xc0059965a0, 0x8f94400, 0xc001e0bc40, 0x8f318c0, 0xc00128d860, 0x8ebe7c0, 0xc000316300, 0x8ea3ba0, 0xc00039c070, ...)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/response.go:57 +0x169a
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers.ListResource.func1(0x8f2d3c0, 0xc00224f668, 0xc008e4d800)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/get.go:276 +0xe17
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints.restfulListResource.func1(0xc0059964e0, 0xc007da2060)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/installer.go:1074 +0x101
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/metrics.InstrumentRouteFunc.func1(0xc0059964e0, 0xc007da2060)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go:271 +0x254
k8s.io/kubernetes/vendor/github.com/emicklei/go-restful.(*Container).dispatch(0xc000e3e630, 0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d800)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/github.com/emicklei/go-restful/container.go:277 +0x985
k8s.io/kubernetes/vendor/github.com/emicklei/go-restful.(*Container).Dispatch(...)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/github.com/emicklei/go-restful/container.go:199
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server.director.ServeHTTP(0x5ac0ffb, 0xe, 0xc000e3e630, 0xc000674af0, 0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d800)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/handler.go:146 +0x4e4
k8s.io/kubernetes/vendor/k8s.io/kube-aggregator/pkg/apiserver.(*proxyHandler).ServeHTTP(0xc001afe310, 0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d800)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/kube-aggregator/pkg/apiserver/handler_proxy.go:108 +0x162
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/mux.(*pathHandler).ServeHTTP(0xc00936a540, 0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d800)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:248 +0x38d
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/mux.(*PathRecorderMux).ServeHTTP(0xc00020ae70, 0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d800)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/mux/pathrecorder.go:234 +0x85
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server.director.ServeHTTP(0x5ac59b2, 0xf, 0xc001a5f8c0, 0xc00020ae70, 0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d800)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/handler.go:154 +0x6c3
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithAuthorization.func1(0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d800)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/filters/authorization.go:64 +0x4fa
net/http.HandlerFunc.ServeHTTP(0xc00403d200, 0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d800)
	/usr/local/google/home/aprindle/Downloads/go1.12.1.linux-amd64/go/src/net/http/server.go:1995 +0x44
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/filters.WithMaxInFlightLimit.func1(0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d800)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/filters/maxinflight.go:160 +0x5c7
net/http.HandlerFunc.ServeHTTP(0xc00442a120, 0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d800)
	/usr/local/google/home/aprindle/Downloads/go1.12.1.linux-amd64/go/src/net/http/server.go:1995 +0x44
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithImpersonation.func1(0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d800)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/filters/impersonation.go:50 +0x1ec3
net/http.HandlerFunc.ServeHTTP(0xc00403d240, 0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d800)
	/usr/local/google/home/aprindle/Downloads/go1.12.1.linux-amd64/go/src/net/http/server.go:1995 +0x44
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/filters.WithAuthentication.func1(0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d700)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/filters/authentication.go:81 +0x527
net/http.HandlerFunc.ServeHTTP(0xc000f62f50, 0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d700)
	/usr/local/google/home/aprindle/Downloads/go1.12.1.linux-amd64/go/src/net/http/server.go:1995 +0x44
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/filters.WithCORS.func1(0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d700)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/filters/cors.go:75 +0x1d7
net/http.HandlerFunc.ServeHTTP(0xc004067ec0, 0x7f678cdfdfa0, 0xc00224f650, 0xc008e4d700)
	/usr/local/google/home/aprindle/Downloads/go1.12.1.linux-amd64/go/src/net/http/server.go:1995 +0x44
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP.func1(0xc004519260, 0xc003058020, 0x8f43c80, 0xc00224f650, 0xc008e4d700)
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/filters/timeout.go:118 +0xb3
created by k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/filters.(*timeoutHandler).ServeHTTP
	/usr/local/google/home/aprindle/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/server/filters/timeout.go:107 +0x1b1

logging error output: "{\"kind\":\"Status\",\"apiVersion\":\"v1\",\"metadata\":{},\"status\":\"Failure\",\"message\":\"aaron-prindle-injected-1: tcp broken\",\"code\":500}\n"
 [podlist-error/v0.0.0 (linux/amd64) kubernetes/$Format [::1]:46486]
```
full logs: https://gist.github.com/aaron-prindle/a9bc329d770987f40ef549b58e03f89d

This bug might affect more than the serialization error outlined.

**Environment**:
- Kubernetes version (use `kubectl version`):
1.14
- Cloud provider or hardware configuration:
Debian GNU/Linux
- OS (e.g: `cat /etc/os-release`):
PRETTY_NAME="Debian GNU/Linux buster/sid"
NAME="Debian GNU/Linux"
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"
- Kernel (e.g. `uname -a`):
Linux "" 4.19.20-1""1-amd64 #1 SMP Debian 4.19.20-1""1 (2019-02-12 > 2018) x86_64 GNU/Linux
- Install tools:
- Others: