关于Nginx proxy_connect_timeout 的问题

你是如何理解proxy_connect_timeout、proxy_read_timeout和proxy_send_timeout 的，这几个参数在nginx 作为proxy时，与后端的 real server通信连接起到什么作用？

问题起源

今天线上环境出现一个问题，在用户访问web时，加载某个页面很慢，有时会出现”504 Gateway Time-out”, 检查了nginx日志后，发现 access.log 记录的该页面请求访问的响应code却是499.（查看日志这一步是后面感到困惑之后才想来的看日志的。为自己的笨脑子感到羞耻／🤦‍♂️）. 因为业务同事一开始反映的问题是数据库查询比较慢，加载完这个页面，光DB这块的查询就消耗了70s左右。思路一下跳到db 上了，查了该页面所用到的sql语句后，发现有一条对user_access_logs 这个表的查询用了将近5s左右。

在查询了该表的大小后，这个表在库里是最大的（这里又涉及到另外一个关于PG 表不断变大的一个问题）。因为这个表存了所有用户的操作记录及其它信息,而查询慢的这个页面是查询了这个3个月时间的数据, 所以用时较久。找到了大概，先去跟业务同事讨论下吧。

解决方案

讨论之后，出来下面2个解决方法:

修改该表的结构，缩小内容，优化查询语句
修改nginx 的超时时间 (临时解决页面504)

实施

为了不影响页面的正常访问，毫无疑问的选择了第二种方案.在经过去官网查询关于proxy timeout 的可选配置后，本来是想针对该域名做设置的，后来发现全局里已经有了这几项配置(proxy_read_timeout、 proxy_send_timeout、proxy_connect_timeout).其配置如下：

http {
    ...

    proxy_connect_timeout 90;
    proxy_send_timeout 300;
    proxy_read_timeout 300;
    send_timeout 300;

    ...
}

看到这，估计大家心里就有点疑惑了。这nginx 全局不是已经设置了proxy_send_timeout 时间为300秒了么？为什么nginx 还会出现 504 timeout 呢?

在带着疑惑的状态下，修改了nginx 的配置，把proxy_connect_timeout的值也增加到300秒,修改后的配置如下：

http {
    ...

    proxy_connect_timeout 300;
    proxy_send_timeout 300;
    proxy_read_timeout 300;
    send_timeout 300;

    ...
}

验证

修改完配置，让业务同事再次测试下，发现页面可以加载出来，没有出现 504 Timeout 提示了。额，这居然是connect超时引起的？而且也是等了和之前差不多的时间(1分钟多一点). 这个因DB 查询慢导致的网页加载超时引发nginx网关超时的问题，暂时得到解决。

疑惑之处

心里还是很困惑，又去看了下官方ngx_http_proxy_module里面对这几个参数的解释.

Note：为了方便理解，我把proxied server 以real server替代，意指upstream 后端的真实主机或服务.

先看下这几个的官方解释： proxy_connect_timeout:

Syntax: proxy_connect_timeout time;
Default:        
proxy_connect_timeout 60s;
Context:        http, server, location

Defines a timeout for establishing a connection with a proxied server. It should be noted that this timeout cannot usually exceed 75 seconds.

定义一个nginx 与real server 建立链接的超时时间,通常不要超过75秒.默认：60s

proxy_read_timeout:

Syntax: proxy_read_timeout time;
Default:        
proxy_read_timeout 60s;
Context:        http, server, location

Defines a timeout for reading a response from the proxied server. The timeout is set only between two successive read operations, not for the transmission of the whole response. If the proxied server does not transmit anything within this time, the connection is closed.

定义一个nginx等待real server响应数据的超时时间,超时只在两次连续的读操作之间设置，而不是用于传输整个响应。如果real server在此时间内没有传输任何内容，则连接将关闭。

proxy_send_timeout:

Syntax: proxy_send_timeout time;
Default:        
proxy_send_timeout 60s;
Context:        http, server, location

Sets a timeout for transmitting a request to the proxied server. The timeout is set only between two successive write operations, not for the transmission of the whole request. If the proxied server does not receive anything within this time, the connection is closed.

定义一个nginx向 real server发送请求的超时时间，超时只在两次连续写入操作之间设置, 而不是用于传输整个请求，如果real server在此时间内没有收到任何内容，则连接将关闭。

分析日志

Note: 流量流向示意： LB–>Nginx–>WebApp

LB 日志

由于LB 这里暂时未接入日志，所以导致这里日志缺失。也是运维工作的不完善之处！我们先从下面两层来分析吧，看能找到线索不。

Nginx 日志

1.1.1.1 - - [19/Jun/2018:11:13:08 +0800] - example.com to: unix:/var/www/example.com/shared/tmp/sockets/puma.sock: "GET /p/dashboard HTTP/1.1" - 499 0 "https://example.com/companies/b66962f4-d29d-49d2-bee0-76c85ce5af72/edit?referer=https%3A%2F%2Fexample.com%2Ffundings%2Ffunding_history%3Fcompany_id%3Db66962f4-d29d-49d2-bee0-76c85ce5af72" "Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.87 Safari/537.36"

1.1.1.1 - - [19/Jun/2018:11:13:08 +0800] - example.com to: unix:/var/www/example.com/shared/tmp/sockets/puma.sock: "GET /p/dashboard HTTP/1.1" - 499 0 "https://example.com/companies/b66962f4-d29d-49d2-bee0-76c85ce5af72/edit?referer=https%3A%2F%2Fexample.com%2Ffundings%2Ffunding_history%3Fcompany_id%3Db66962f4-d29d-49d2-bee0-76c85ce5af72" "Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.87 Safari/537.36"

1.1.1.1 - - [19/Jun/2018:11:32:48 +0800] - example.com to: unix:/var/www/example.com/shared/tmp/sockets/puma.sock: "GET /p/dashboard HTTP/1.1" - 499 0 "https://example.com/fundings/manage?funding_id=14990" "Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.87 Safari/537.36"

1.1.1.1 - - [19/Jun/2018:11:37:21 +0800] - example.com to: unix:/var/www/example.com/shared/tmp/sockets/puma.sock: "GET /p/dashboard HTTP/1.1" - 499 0 "https://example.com/fundings/manage?funding_id=14990" "Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/67.0.3396.87 Safari/537.36"

Web应用日志

{"mddethod":"GET","path":"/sp/dashboard","format":"html","controller":"Admin::DashboardController","action":"index","status":200,"duration":66678.25,"view":285.17,"db":66380.07,"params":{},"referrer":"https://example.com/edit?referer=https%3A%2F%2Fexample.com%2Ffundings%2Ffunding_history%3Fcompany_id%3Db66962f4-d29d-49d2-bee0-76c85ce5af72","user_id":13314,"session_id":"5e5a70a5401919c405114094ecad5967","time":"2018-06-19 11:12:18 +0800","headers":"#<ActionDispatch::Http::Headers:0x007f0ca6c4b9e0>"}

{"method":"GET","path":"/sp/dashboard","format":"html","controller":"Admin::DashboardController","action":"index","status":200,"duration":66556.56,"view":355.28,"db":66188.07,"params":{},"referrer":"https://example.com/edit?referer=https%3A%2F%2Fexample.com%2Ffundings%2Ffunding_history%3Fcompany_id%3Db66962f4-d29d-49d2-bee0-76c85ce5af72","user_id":13314,"session_id":"5e5a70a5401919c405114094ecad5967","time":"2018-06-19 11:12:18 +0800","headers":"#<ActionDispatch::Http::Headers:0x007f0ca1cd2ee0>"}

{"method":"GET","path":"/sp/dashboard","format":"html","controller":"Admin::DashboardController","action":"index","status":200,"duration":64519.48,"view":326.36,"db":64181.76,"params":{},"referrer":"https://example.com/manage?funding_id=14990","user_id":13314,"session_id":"5e5a70a5401919c405114094ecad5967","time":"2018-06-19 11:31:58 +0800","headers":"#<ActionDispatch::Http::Headers:0x007f0c6b4f28a0>"}

{"method":"GET","path":"/sp/dashboard","format":"html","controller":"Admin::DashboardController","action":"index","status":200,"duration":64343.34,"view":299.02,"db":64032.83,"params":{},"referrer":"https://example.com/manage?funding_id=14990","user_id":13314,"session_id":"5e5a70a5401919c405114094ecad5967","time":"2018-06-19 11:36:31 +0800","headers":"#<ActionDispatch::Http::Headers:0x007f0c10e0d670>"}

仔细观察一下nginx 和 web 应用的日志可以看出2条线索： * 关于这个页面的日记录志响应code基本都是499， 499 又称为客户端系列的错误代码，一般是客户端在与服务器建立连接时，客户端如果在指定时间内接收不到服务器的响应，便会主动关闭主动关闭这个连接，这时nginx服务器便会记录一个499 记录。 * web app里的日志和 nginx 里面的日志记录时间相差 50s 仔细观察下时间，我们可以看出，同一条请求在流向最终web应用时，以及应用接收到的请求时间，和nginx 出现499日志记录的时间，中间都是相差了50秒。拿2个文件的第一条日志来说，webapp在11:12:18时间段接收到nginx的请求，然而webapp整个处理完请求后，用了66678.25ms, 即66秒，而nginx日志在发给webapp请求到第50秒时，即 11:13:08 时间后，出现了一条499的日志，也就是说客户端在指定时间内没有得到nginx server 的响应，主动断开了与它的链接。这个时间应该是设置的50s。

大致的分析之后，是不是就清晰了很多呢? 但大家也许会疑惑了，一开始出现的问题现象，不是访问这个页面慢，会出现504 timeout的提示么，怎么这会又成了499 的错误提示了呢？这主要因为我忘记了把最前面的LB算进来。因为所有流量都要这样走，User Browser --> Cloud LB --> Nginx --> Web App . 在这种场景下， LB 对于nginx 来说，它就是一个客户端(client), 所以这个499 是针对LB的访问而返回的。而LB这里设置了超时时间刚好是50秒(检查得知)，所以，过了50秒后，如果nginx 还不能返回数据给LB，那么LB就会主动断开，并且返给最终User Browser “504 Timeout”.

至此，基本上用原理解释了为什么会有504、499 不同的http响应code。那么问题又回来了，为什么设置了 proxy_connect_timeout后，可以正常访问了？这里其实是一个乌龙，在修改完nginx配置后，其实业务同事在继续测试下，网页访问可以正常加载，这刚好说明了在db那块，恰好这个查询是没有耗时，或者说有耗时但没有影响整体的请求访问。没有达到LB设置的50秒，也就不会出现Gateway timeout。只是偶尔会出现查询超时才会导致LB返回504 给最终user（browser）.

结论

最终的临时解决方案是把LB的超时时间设置大于50s，根据业务需要，修改成了2分钟.后续可能会配合业务针对db 进行些优化吧。

aliasmee's blog