{"action":"created","issue":{"url":"https://api.github.com/repos/golang/go/issues/16958","repository_url":"https://api.github.com/repos/golang/go","labels_url":"https://api.github.com/repos/golang/go/issues/16958/labels{/name}","comments_url":"https://api.github.com/repos/golang/go/issues/16958/comments","events_url":"https://api.github.com/repos/golang/go/issues/16958/events","html_url":"https://github.com/golang/go/issues/16958","id":174612587,"number":16958,"title":"net/http: ReadTimeout Breaks Server CloseNotify Functionality For Keep-Alive Connections","user":{"login":"prabrisat1","id":1643824,"avatar_url":"https://avatars.githubusercontent.com/u/1643824?v=3","gravatar_id":"","url":"https://api.github.com/users/prabrisat1","html_url":"https://github.com/prabrisat1","followers_url":"https://api.github.com/users/prabrisat1/followers","following_url":"https://api.github.com/users/prabrisat1/following{/other_user}","gists_url":"https://api.github.com/users/prabrisat1/gists{/gist_id}","starred_url":"https://api.github.com/users/prabrisat1/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/prabrisat1/subscriptions","organizations_url":"https://api.github.com/users/prabrisat1/orgs","repos_url":"https://api.github.com/users/prabrisat1/repos","events_url":"https://api.github.com/users/prabrisat1/events{/privacy}","received_events_url":"https://api.github.com/users/prabrisat1/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":8,"created_at":"2016-09-01T20:02:24Z","updated_at":"2016-09-03T04:07:14Z","closed_at":null,"body":"### Issue\r\nGO1.7's functionality for HTTP 1.1's keep-alive, net/http.Server.ReadTimeout, and net/http.CloseNotifier is not consistent with the documented and/or expected behavior, and cannot be used together properly. The timer created by setting the server's readTimeout value is reset only at the end of **processing** each request and is not paused/reset when we have finished **reading** in each request, causing CloseNotify() to signal without cause.\r\n\r\n### What did I do\r\nThis test creates a simple http server and then sends 2 requests, each of which takes 40ms of processing time with a 70ms gap between them, responding 200OK if the 40ms of work completes, and 503 if it receives a closeNotify signal before finishing that work.\r\n\r\n### Expected Result\r\nWe should receive 2 200 OK messages and not receive a signal from CloseNotify().\r\n\r\nWe have a readTimeout of 100ms, and a 70ms delay between receiving a response for the first request and sending the second request, so both requests should be read within the timeout and be able to complete their work.\r\n\r\n### Actual Result\r\nWe actually see that during the second request, we receive a closeNotify() signal approximately 30ms after the client has sent the second request. At this time we have clearly read the second request and started processing it with a still alive TCP connection, but still receive a closeNotify() signal, which should not be happening. There is also an attached wireshark log showing this.\r\n\r\n```go\r\npackage main\r\n\r\nimport (\r\n\t\"io\"\r\n\t\"io/ioutil\"\r\n\t\"net/http\"\r\n\t\"net/http/httptest\"\r\n\t\"sync\"\r\n\t\"testing\"\r\n\t\"time\"\r\n)\r\n\r\nfunc TestServerKeepAliveReadTimeoutCloseNotify(t *testing.T) {\r\n\tvar startMu sync.Mutex\r\n\tvar start time.Time\r\n\r\n\ttestServer := httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {\r\n\t\tcn := w.(http.CloseNotifier)\r\n\t\tselect {\r\n\t\tcase <-time.After(40 * time.Millisecond):\r\n\t\t\tw.WriteHeader(http.StatusOK)\r\n\t\tcase <-cn.CloseNotify():\r\n\t\t\tstartMu.Lock()\r\n\t\t\tdelta := time.Since(start)\r\n\t\t\tstartMu.Unlock()\r\n\t\t\tt.Errorf(\"Unexpected CloseNotify received after %s\", delta)\r\n\t\t\tw.WriteHeader(http.StatusServiceUnavailable)\r\n\t\t}\r\n\t}))\r\n\ttestServer.Config.ReadTimeout = 100 * time.Millisecond\r\n\ttestServer.Start()\r\n\tdefer testServer.Close()\r\n\r\n\tfor i := 0; i < 2; i++ {\r\n\t\tstartMu.Lock()\r\n\t\tstart = time.Now()\r\n\t\tstartMu.Unlock()\r\n\r\n\t\tresp, err := http.Get(testServer.URL)\r\n\t\tif err != nil {\r\n\t\t\tt.Fatal(err)\r\n\t\t}\r\n\t\t_, err = io.Copy(ioutil.Discard, resp.Body)\r\n\t\tif err != nil {\r\n\t\t\tt.Fatal(err)\r\n\t\t}\r\n\t\terr = resp.Body.Close()\r\n\t\tif err != nil {\r\n\t\t\tt.Fatal(err)\r\n\t\t}\r\n\r\n\t\ttime.Sleep(70 * time.Millisecond)\r\n\t}\r\n}\r\n```\r\n\r\nTest output\r\n```\r\n$ go test notifierIssue_test.go \r\n--- FAIL: TestServerKeepAliveReadTimeoutCloseNotify (0.22s)\r\n\tnotifierIssue_test.go:26: Unexpected CloseNotify received after 30.752781ms\r\nFAIL\r\nFAIL\tcommand-line-arguments\t0.225s\r\n```\r\n[wSharkLogs.pcapng.zip](https://github.com/golang/go/files/450479/wSharkLogs.pcapng.zip)\r\n\r\n### Potential Fix\r\nCurrently the read timeout is only reset here: https://github.com/golang/go/blob/go1.7/src/net/http/server.go#L749 after a request has finished being processed and we start waiting on the next one. However, the timeout is never paused/reset for the period between the end of reading the request and the end of sending the response, as it should be. \r\n\r\n### What version of Go are you using (`go version`)?\r\ngo version go1.7 darwin/amd64\r\n\r\n### What operating system and processor architecture are you using (`go env`)?\r\nGOARCH=\"amd64\"\r\nGOBIN=\"\"\r\nGOEXE=\"\"\r\nGOHOSTARCH=\"amd64\"\r\nGOHOSTOS=\"darwin\"\r\nGOOS=\"darwin\"\r\nGORACE=\"\"\r\nGOROOT=\"/usr/local/go\"\r\nGOTOOLDIR=\"/usr/local/go/pkg/tool/darwin_amd64\"\r\nCC=\"clang\"\r\nGOGCCFLAGS=\"-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/4r/1g2c4css78b1yn2q32dmqqm0l05w9h/T/go-build102138663=/tmp/go-build -gno-record-gcc-switches -fno-common\"\r\nCXX=\"clang++\"\r\nCGO_ENABLED=\"1\""},"comment":{"url":"https://api.github.com/repos/golang/go/issues/comments/244525254","html_url":"https://github.com/golang/go/issues/16958#issuecomment-244525254","issue_url":"https://api.github.com/repos/golang/go/issues/16958","id":244525254,"user":{"login":"prabrisat1","id":1643824,"avatar_url":"https://avatars.githubusercontent.com/u/1643824?v=3","gravatar_id":"","url":"https://api.github.com/users/prabrisat1","html_url":"https://github.com/prabrisat1","followers_url":"https://api.github.com/users/prabrisat1/followers","following_url":"https://api.github.com/users/prabrisat1/following{/other_user}","gists_url":"https://api.github.com/users/prabrisat1/gists{/gist_id}","starred_url":"https://api.github.com/users/prabrisat1/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/prabrisat1/subscriptions","organizations_url":"https://api.github.com/users/prabrisat1/orgs","repos_url":"https://api.github.com/users/prabrisat1/repos","events_url":"https://api.github.com/users/prabrisat1/events{/privacy}","received_events_url":"https://api.github.com/users/prabrisat1/received_events","type":"User","site_admin":false},"created_at":"2016-09-03T04:07:14Z","updated_at":"2016-09-03T04:07:14Z","body":"You're correct that as soon as the server finishes the first request it resets the deadline. That is the problem, the readtimeout is reset after first request is completed, not after the message is read specifically.\r\n\r\nIts much clearer if you take a look at the attached wireshark logs. The read timeout is not being reset after the request is read, but after the request has been read and the handler's work has been completed. In the above example, the client receives a 200 OK ~41ms after process starts, and the readTimeout is reset here @ 41ms. The server receives the next request at ~116ms, so ~75ms later. The message is just a GET with no body and takes ~1-2ms to be read, a total of ~77ms, so it should we have read a message within the readTimeout right? This isn't true because the readTimeout is limiting the readTime and the time required for the handler to complete. which is why we receive a closeNotify signal at ~142ms before our 40ms of work on the request completes at ~117ms.\r\n\r\nEffectively, the current readTimeout measures (time spent waiting for a request + time spend reading request + time spent doing work on the request) when it should really only represent either (time waiting on request + time reading request) or even just (time spent reading request) for the name readTimeout to actually be applicable."}}
{"actor":{"display_login":"prabrisat1"}}