{"action":"created","issue":{"url":"https://api.github.com/repos/nghttp2/nghttp2/issues/703","repository_url":"https://api.github.com/repos/nghttp2/nghttp2","labels_url":"https://api.github.com/repos/nghttp2/nghttp2/issues/703/labels{/name}","comments_url":"https://api.github.com/repos/nghttp2/nghttp2/issues/703/comments","events_url":"https://api.github.com/repos/nghttp2/nghttp2/issues/703/events","html_url":"https://github.com/nghttp2/nghttp2/issues/703","id":181897710,"number":703,"title":"nghttpx seems to delay the request to squid sometimes.","user":{"login":"joeshae","id":6749515,"avatar_url":"https://avatars.githubusercontent.com/u/6749515?v=3","gravatar_id":"","url":"https://api.github.com/users/joeshae","html_url":"https://github.com/joeshae","followers_url":"https://api.github.com/users/joeshae/followers","following_url":"https://api.github.com/users/joeshae/following{/other_user}","gists_url":"https://api.github.com/users/joeshae/gists{/gist_id}","starred_url":"https://api.github.com/users/joeshae/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/joeshae/subscriptions","organizations_url":"https://api.github.com/users/joeshae/orgs","repos_url":"https://api.github.com/users/joeshae/repos","events_url":"https://api.github.com/users/joeshae/events{/privacy}","received_events_url":"https://api.github.com/users/joeshae/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/nghttp2/nghttp2/labels/nghttpx","name":"nghttpx","color":"c7def8"}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":16,"created_at":"2016-10-09T16:55:40Z","updated_at":"2016-10-12T15:30:23Z","closed_at":null,"body":"nghttpx is used as a h2 proxy frontend, which backend is squid.\r\nnghttpx and squid are running on the same dedicated server.\r\nIt's usually no problem when you browse the websites, but it takes long time for some requests occasionally. \r\nIf you refresh the page when this issue happened, the issue disappears weirdly, even if you clean the cache before refreshing.\r\nThis occasional issue exists in both the latest stable Chrome and Firefox, so I don't think it's a browser's bug.\r\n\r\nLet's take a look at an example in Firefox's Developer Tools:\r\n\r\n![firefox](https://cloud.githubusercontent.com/assets/6749515/19221938/7938a17a-8e7f-11e6-98f0-fe22641433d3.png)\r\n\r\n\r\n\r\nThis is the log from nghttpx about this request:\r\n\r\n![nghttpx](https://cloud.githubusercontent.com/assets/6749515/19221976/60fdd908-8e80-11e6-8f31-2e0a373c13e7.png)\r\n\r\n\r\n\r\nThis is the log from squid about this request:\r\n\r\n![squid](https://cloud.githubusercontent.com/assets/6749515/19221974/49446f70-8e80-11e6-9329-fffb3be7f06f.png)\r\n\r\n\r\nSome analysis:\r\n\r\n1) Both nghttpx and squid won't print the log until a request is finished.\r\nSo from the same timestamps in nghttpx and squid, we can see, when squid returns the http response to nghttpx, **it takes less than 1 second for nghttpx to deliver it to the browser**. \r\nIf the network was slow when nghttpx deliveried the response to the browser, the timestamp in nghttpx would be later than the timestamp in squid.\r\n\r\n\r\n2) Take a look at the \"145, -, 145, 145\" in squid log.\r\nCorresponding squid logformat is \"%tr,%dt,%<pt,%<tt\", which explains at:\r\nhttp://www.squid-cache.org/Doc/config/logformat/\r\n\r\n%tr\t    Response time (milliseconds)\r\n%dt\t    Total time spent making DNS lookups (milliseconds)\r\n%<pt    Peer response time in milliseconds. The timer starts when the last request byte is sent to the next hop and stops when the last response byte is received.\r\n%<tt\t    Total time in milliseconds. The timer starts with the first connect request (or write I/O) sent to the first selected peer. The timer stops with the last I/O with the last peer.\r\n\r\nIt means **it takes only 145 milliseconds for squid to finish the whole request**.\r\n\r\n\r\n3) Take a look at the \"15.180\" in nghttpx log.\r\nIt means **it takes 15.180 seconds for nghttpx from receiving the request to finishing delivering the response to the client.**\r\n\r\n\r\nSo there is only one possibility:\r\nnghttpx didn't transfer the raw request to squid at the beginning, which lasted for 15 seconds.\r\n\r\nWhat's your opinion?\r\n"},"comment":{"url":"https://api.github.com/repos/nghttp2/nghttp2/issues/comments/253247709","html_url":"https://github.com/nghttp2/nghttp2/issues/703#issuecomment-253247709","issue_url":"https://api.github.com/repos/nghttp2/nghttp2/issues/703","id":253247709,"user":{"login":"joeshae","id":6749515,"avatar_url":"https://avatars.githubusercontent.com/u/6749515?v=3","gravatar_id":"","url":"https://api.github.com/users/joeshae","html_url":"https://github.com/joeshae","followers_url":"https://api.github.com/users/joeshae/followers","following_url":"https://api.github.com/users/joeshae/following{/other_user}","gists_url":"https://api.github.com/users/joeshae/gists{/gist_id}","starred_url":"https://api.github.com/users/joeshae/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/joeshae/subscriptions","organizations_url":"https://api.github.com/users/joeshae/orgs","repos_url":"https://api.github.com/users/joeshae/repos","events_url":"https://api.github.com/users/joeshae/events{/privacy}","received_events_url":"https://api.github.com/users/joeshae/received_events","type":"User","site_admin":false},"created_at":"2016-10-12T15:30:23Z","updated_at":"2016-10-12T15:30:23Z","body":"On my server, squid works on local port 41~47.\r\n\r\nWhen I see these logs in nghttpx.log:\r\n\r\n```\r\n12/Oct/2016:22:57:45 +0800 PID6900 [WARN] shrpx_http_downstream_connection.cc:75 [DCONN:0x7f6f202e1c80] Connect time out; addr=127.0.0.1:47\r\n12/Oct/2016:22:57:45 +0800 PID6900 [WARN] shrpx_connect_blocker.cc:93 Could not connect 1 times in a row; sleep for 1.28845 seconds\r\n12/Oct/2016:23:00:31 +0800 PID6900 [WARN] shrpx_http_downstream_connection.cc:75 [DCONN:0x7f6f220cdd00] Connect time out; addr=127.0.0.1:47\r\n12/Oct/2016:23:00:31 +0800 PID6900 [WARN] shrpx_connect_blocker.cc:93 Could not connect 1 times in a row; sleep for 1.47325 seconds\r\n12/Oct/2016:23:07:33 +0800 PID6900 [WARN] shrpx_http_downstream_connection.cc:75 [DCONN:0x7f6f1f063180] Connect time out; addr=127.0.0.1:47\r\n12/Oct/2016:23:07:33 +0800 PID6900 [WARN] shrpx_connect_blocker.cc:93 Could not connect 1 times in a row; sleep for 1.91279 seconds\r\n12/Oct/2016:22:57:45 +0800 PID6900 [WARN] shrpx_http_downstream_connection.cc:75 [DCONN:0x7f6f202e1c80] Connect time out; addr=127.0.0.1:47\r\n12/Oct/2016:22:57:45 +0800 PID6900 [WARN] shrpx_connect_blocker.cc:93 Could not connect 1 times in a row; sleep for 1.28845 seconds\r\n12/Oct/2016:23:00:31 +0800 PID6900 [WARN] shrpx_http_downstream_connection.cc:75 [DCONN:0x7f6f220cdd00] Connect time out; addr=127.0.0.1:47\r\n12/Oct/2016:23:00:31 +0800 PID6900 [WARN] shrpx_connect_blocker.cc:93 Could not connect 1 times in a row; sleep for 1.47325 seconds\r\n12/Oct/2016:23:07:33 +0800 PID6900 [WARN] shrpx_http_downstream_connection.cc:75 [DCONN:0x7f6f1f063180] Connect time out; addr=127.0.0.1:47\r\n12/Oct/2016:23:07:33 +0800 PID6900 [WARN] shrpx_connect_blocker.cc:93 Could not connect 1 times in a row; sleep for 1.91279 seconds\r\n12/Oct/2016:23:23:24 +0800 PID6900 [WARN] shrpx_http_downstream_connection.cc:75 [DCONN:0x7f6f20733a80] Connect time out; addr=127.0.0.1:47\r\n12/Oct/2016:23:23:24 +0800 PID6900 [WARN] shrpx_connect_blocker.cc:93 Could not connect 1 times in a row; sleep for 1.53518 seconds\r\n```\r\n\r\nI ran this command to see there was a port pair (127.0.0.1:47, 127.0.0.1:52884), which exists for a very very long period:\r\n\r\n```\r\n[root@cn2-qz ~]# lsof -Pni:41 | grep CLOSE_WAIT; lsof -Pni:42 | grep CLOSE_WAIT; lsof -Pni:43 | grep CLOSE_WAIT; lsof -Pni:44 | grep CLOSE_WAIT; lsof -Pni:45 | grep CLOSE_WAIT; lsof -Pni:46 | grep CLOSE_WAIT; lsof -Pni:47 | grep CLOSE_WAIT; lsof -Pni:48 | grep CLOSE_WAIT;\r\n\r\nnghttpx 6901   root  159u  IPv4 2401007      0t0  TCP 127.0.0.1:32981->127.0.0.1:46 (CLOSE_WAIT)\r\nsquid   6831 nobody  330u  IPv6 3697396      0t0  TCP 127.0.0.1:47->127.0.0.1:52884 (CLOSE_WAIT)\r\n```"}}
{"actor":{"display_login":"joeshae"}}