分类： LINUX
2012-11-29 14:57:30
对于一个worker，只维护自己的upstream状态表，不存在进程间通讯的问题
本示例中，upstream backend包含5个member，为54-58，连接超时为30秒，其余参数默认（fail_timeout默认10秒）
ERROR LOG:
2012/11/28 22:26:15 [error] 2943#0: *1302597622 no live upstreams while connecting to upstream, client: 117.136.9.124, server: webapps.ccc.com, request: "HEAD /mobile/web/search.jsp?keyword=%AE HTTP/1.1", upstream: "%AE", host: "s.ccc.com"
ACCESS LOG:
117.136.9.124 - - [28/Nov/2012:22:26:15 +0800] "HEAD /mobile/web/search.jsp?keyword=%AE HTTP/1.1" 502 0 "-" "Apache-HttpClient/UNAVAILABLE (java 1.4)" s.ccc.com - 11.22.33.57:8080, backend 504, 502 30.009, 0.000 30.009 -
在22:26:15,记录了一条502,access log显示nginx先尝试从57取数据,30秒后超时,upstream状态表里已经没有up的成员,那么就返回502
据此,这个连接进来的时间应该是30秒前,也就是22:25:45.也就是说,在这个时间点,upstream状态表成员的down标志是在之前10秒内被标记的,一下为日志片段:
# cat error.log | grep "2012/11/28 22:25" | grep 2943\#|grep "upstream timed out" | perl -n -e '$_ =~ /^([0-9]+\/[0-9]+\/[0-9]+\ [0-9]+:[0-9]+:[0-9]+).*(\ [0-9]+)\#.*client:\ ([0-9]+\.[0-9]+\.[0-9]+\.[0-9]+).*upstream:\ \"http:\/\/([0-9]+\.[0-9]+\.[0-9]+\.[0-9]+)/;print "$1 $2 $4\n";'|grep 11.22.33
2012/11/28 22:25:15 2943 11.22.33.57
2012/11/28 22:25:21 2943 11.22.33.55
2012/11/28 22:25:29 2943 11.22.33.58
2012/11/28 22:25:30 2943 11.22.33.58
2012/11/28 22:25:37 2943 11.22.33.56
2012/11/28 22:25:43 2943 11.22.33.55
2012/11/28 22:25:45 2943 11.22.33.58
2012/11/28 22:25:49 2943 11.22.33.55
2012/11/28 22:25:49 2943 11.22.33.54
2012/11/28 22:25:50 2943 11.22.33.56
2012/11/28 22:25:52 2943 11.22.33.58
2012/11/28 22:25:54 2943 11.22.33.54
2012/11/28 22:25:54 2943 11.22.33.58
2012/11/28 22:25:55 2943 11.22.33.56
2012/11/28 22:25:59
2943 11.22.33.54
黄色区域为45秒往前10秒内被标记成down的成员的标记过程日志，显示只有54和57是up的。
（为什么在后面还会有同样的成员被标记成down的日志？那是因为，一个连接进来时，如果在30秒超时未结束时，一个新的连接进来了，那么这个upstream成员是不会被标记成down的，只有30秒超时结束后，才会被标记成down，那么，在22:25:45以后被标记成down的55,56和58再次出现就是这个原因）
# cat error.log | grep "2012/11/28 22:26" | grep 2943\#|grep "upstream timed out" | perl -n -e '$_ =~ /^([0-9]+\/[0-9]+\/[0-9]+\ [0-9]+:[0-9]+:[0-9]+).*(\ [0-9]+)\#.*client:\ ([0-9]+\.[0-9]+\.[0-9]+\.[0-9]+).*upstream:\ \"http:\/\/([0-9]+\.[0-9]+\.[0-9]+\.[0-9]+)/;print "$1 $2 $4\n";'|grep 11.22.33
2012/11/28 22:26:04 2943 11.22.33.57
2012/11/28 22:26:06 2943 11.22.33.55
2012/11/28 22:26:06 2943 11.22.33.54
2012/11/28 22:26:13 2943 11.22.33.58
2012/11/28 22:26:15 2943 11.22.33.57
2012/11/28 22:26:25 2943 11.22.33.57
2012/11/28 22:26:25 2943 11.22.33.57
2012/11/28 22:26:33 2943 11.22.33.55
2012/11/28 22:26:36 2943 11.22.33.56
2012/11/28 22:26:39 2943 11.22.33.56
2012/11/28 22:26:41 2943 11.22.33.58
2012/11/28 22:26:55 2943 11.22.33.58
那为什么access log里只有57出现了？那是因为在22:26:15之前10秒内，54被标记成down，而当57超时后，nginx想去尝试54的时候，发现54状态是down的，所以直接返回的backend 502。
绿色区域显示在22:26:15时57的30秒超时结束，被标记成down，从而有了error log和access log的记录。
