故障日期: 2016年08月15日
RestHub: 基于Nginx+lua實現(xiàn)的一個API網(wǎng)關產(chǎn)品
一. 故障發(fā)現(xiàn)
系統(tǒng)報警，支付服務某個接口有兩次調(diào)用失敗，錯誤碼為502
502 BAD GATEWAY
The server, while acting as a gateway or proxy, received an invalid response from an inbound server it accessed while attempting to fulfill the request.
--摘自https://httpstatuses.com/502
二. 第一反應
根據(jù)以往的經(jīng)驗，502錯誤大多數(shù)時候是由于后端服務器拒絕連接引起的，常見的情況是服務沒有啟動(沒有監(jiān)聽服務端口)。
于是，馬上和開發(fā)、運維的同學詢問支付系統(tǒng)是否做過升級，答案是沒有，而且，運維同學同時也查看了支付的后端服務(Tomcat)并沒有發(fā)現(xiàn)異常，也沒有發(fā)現(xiàn)重啟。
這個時候，基本可以斷定是RestHub出了故障。
我們參加過一個項目的開發(fā)，有位高級工程師確信select系統(tǒng)調(diào)用在Solaris上有問題。再多的勸說或邏輯也無法改變他的想法（這臺機器上的所有其他網(wǎng)絡應用都工作良好這一事實也一樣無濟于事）。他花了數(shù)周時間編寫繞開這一問題的代碼，因為某種奇怪的原因，卻好像并沒有解決問題。當最后被迫坐下來、閱讀關于select的文檔時，他在幾分鐘之內(nèi)就發(fā)現(xiàn)并糾正了問題?，F(xiàn)在每當有人開始因為很可能是我們自己的故障而抱怨系統(tǒng)時，我們就會使用“select沒有問題”作為溫和的提醒。
--摘自《程序員修煉之道》
這本書我讀過很多遍，顯然，我又忘了！??！
三. Resthub排障
RestHub是基于Nginx+lua實現(xiàn)的，所以錯誤日志就在Nginx自己的日志文件里，如果你熟悉Nginx的話，那么這里的日志格式應該很容易讀懂。
日志內(nèi)容
查看Resthub日志，發(fā)現(xiàn)確實支付業(yè)務的一個接口調(diào)用兩次失敗
2016/08/15 20:34:16 [error] 20486#0: *4076751 connect() failed (111: Connection refused) while connecting to upstream, client: 202.106.222.82, server: localhost, request: "POST /pay/v1/collect HTTP/1.0", subrequest: "http://Pay/api/v1/collect.htm", upstream: "http://127.0.53.53:80/api/v1/collect.htm?__v=v1&__trace_id=10.19.33.237-10982-20486-4076751-1-1471264456.065&__real_ip=202.106.222.82", host: "apis.qianbao.com"
2016/08/15 20:34:16 [error] 11174#0: *4076719 connect() failed (111: Connection refused) while connecting to upstream, client: 202.106.222.82, server: localhost, request: "POST /pay/v1/collect HTTP/1.0", subrequest: "http://Pay/api/v1/collect.htm", upstream: "http://127.0.53.53:80/api/v1/collect.htm?__v=v1&__trace_id=10.19.33.238-10982-11174-4076719-1-1471264456.799&__real_ip=202.106.222.82", host: "apis.qianbao.com"
最明顯錯誤信息
下面的錯誤信息也驗證了，我們對于502錯誤碼的判斷。
connect() failed (111: Connection refused)
但是，根據(jù)運維同學的信息，后端服務并沒有出現(xiàn)故障，所以Connection refused的動作應該不是后端服務的行為，再仔細查看日志，發(fā)現(xiàn)一點端倪
subrequest: "http://Pay/api/v1/collect.htm", upstream: "http://127.0.53.53:80/api/v1/collect.htm
Pay是支付服務的upstream的名字，為什么Nginx把他解析(resolv)到127.0.53.53, why?，這明顯不科學嘛！
好吧，事情講到現(xiàn)在，需要簡單說一下RestHub關于Upstream的設計思路啦，要不然你就暈啦
RestHub使用upstream的方式
這里涉及到數(shù)據(jù)庫中的兩個表
-
api_version保存api的接口信息，包括請求方法，路徑，upstream名稱 -
upstream保存upstream的服務器配置
那么，這時候帶來3個問題
- 當upstream表更新時，需要通知resthub重新生成upstream的配置文件
- 當api_version表更新時，需要通知resthub重新刷新api_data的緩存
- 當upstream表更新時，需要通知resthub重新刷新api_data的緩存
但是，實際代碼中，忽略了第三點。
故障是怎么被觸發(fā)的
按照支付同學的要求，支付服務的upstream名稱由Pay改為pay_biz，結(jié)果，resthub重新生成upstream的配置文件，但是沒有更新api_data(api_data中還在引用稱為Pay的upstream名字)，從日志中可以印證一下
subrequest: "http://Pay/api/v1/collect.htm", upstream: "http://127.0.53.53:80/api/v1/collect.htm
這樣的話，日志中出現(xiàn)Pay就可以解釋通啦。我們再回到前面一個問題來，為什么Pay會解析到127.0.53.53
resthub的配置文件
這是resthub的轉(zhuǎn)發(fā)邏輯的關鍵配置
location ~ ^http {
resolver 192.168.1.231;
internal;
proxy_pass $uri$is_args$args;
}
從現(xiàn)象上看，Nginx找不到名稱為Pay的upstream，就去DNS服務器去解析，下面是Nginx官方文檔
proxy_pass http://$host$request_uri;
In this case, the server name is searched among the described server groups, and, if not found, is determined using a resolver.
最后一個問題
為什么pay會解析到127.0.53.53呢？
我們先來做個實驗
[root@DEV-161 ~] $ ping pay
PING pay (127.0.53.53) 56(84) bytes of data.
64 bytes from 127.0.53.53: icmp_seq=1 ttl=64 time=0.030 ms
64 bytes from 127.0.53.53: icmp_seq=2 ttl=64 time=0.038 ms
64 bytes from 127.0.53.53: icmp_seq=3 ttl=64 time=0.034 ms
^C
--- pay ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2027ms
rtt min/avg/max/mdev = 0.030/0.034/0.038/0.003 ms
確實，pay被解析到了。好吧，是時候求助google啦。下面是google告訴我的
ICANN Approves Name Collision Occurrence Management Framework.
Special IP Address (127.0.53.53) Alerts System Administrators of Potential Issue
大致意思就是，pay之前是頂級域名，但是現(xiàn)在已經(jīng)廢棄啦，各位管理員該注意啦。除了pay之外，還有很多其他以常見單詞命名的頂級域名。
啟示
為了避免誤用被廢棄的頂級域名(以單詞命名)，upstream的名稱最好加上項目名稱，或者簡單一點就是把名字變的更長一些，這樣就能避開一些不容易發(fā)現(xiàn)的巨坑。
