摘要：一看果然是在響應(yīng)發(fā)出后報(bào)的錯(cuò)，但日志沒有反應(yīng)出報(bào)錯(cuò)的具體位置。而我期望的當(dāng)前請求直接終止，不應(yīng)該使用而是。自起，執(zhí)行成功返回，失敗則返回和錯(cuò)誤描述信息。

我們基于Vanilla開發(fā)了一個(gè)類似于一個(gè)網(wǎng)關(guān)的流量分發(fā)服務(wù)，在原來的業(yè)務(wù)線上對不同的業(yè)務(wù)使用不同的后端（PHP、Python、Lua...）進(jìn)行處理，最近在緊鑼密鼓的測試（當(dāng)然這里咱們主要看問題），在掃蕩日志的過程中發(fā)現(xiàn)有這樣的一條 [error] （日志已打碼）

2016/03/01 16:35:36 [error] 32462#0: *1 attempt to set ngx.status after sending out response headers while sending to client, client: xx.xx.xx.xx, server: x.sina.cn, request: "GET /xxx HTTP/1.1", host: "xx.sina.cn:9110"

沒錯(cuò)，就是條： attempt to set ngx.status after sending out response headers while sending to client，大致意思是我在響應(yīng)頭已經(jīng)發(fā)出后又嘗試對 ngx.status 進(jìn)行了修改，可是我肯定不會(huì)想那么干的，而且頁面請求看著明明是正常的。

本著認(rèn)真負(fù)責(zé)的態(tài)度，我又對代碼邏輯和寫法前前后后梳理數(shù)次，然事實(shí)上并沒有發(fā)現(xiàn)我試圖那么干，至少本意是確定的。面對這個(gè)幽靈般的錯(cuò)誤，一個(gè)程序員的直覺告訴我，肯定是我寫了一個(gè)bug？或者我的某些邏輯觸發(fā)了Vanilla的bug？或者觸發(fā)了OpenResty的bug？越想越激動(dòng)，我必須把它找出來。

為了避免大家混淆各種Vanilla，這里先附上Vanilla項(xiàng)目地址：

Github：https://github.com/idevz/vanilla

GitOSC：http://git.oschina.net/idevz/vanilla

邏輯上肉眼沒看出什么問題，只能通過debug來解決。到底哪行報(bào)出來的錯(cuò)誤呢？在公司開發(fā)機(jī)上添加 --with-debug 參數(shù)重新編譯了OpenResty，打開debug日志。

2016/03/01 16:35:36 [debug] 32462#0: *1 posix_memalign: 0000000000E8DA10:4096 @16
2016/03/01 16:35:36 [debug] 32462#0: *1 HTTP/1.1 200 OK
Server: openresty/1.9.3.1
Date: Tue, 01 Mar 2016 08:35:36 GMT
Content-Type: text/html; charset=UTF-8
Transfer-Encoding: chunked
Connection: keep-alive
Power-By: Vanilla-0.1.0-rc4
Set-Cookie: xx=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/; domain=.sina.cn
Set-Cookie: xx=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; Max-Age=0; path=/; domain=.sina.cn
cache-status: MISS
X-Powered-By: PHP/7.0.0

2016/03/01 16:35:36 [debug] 32462#0: *1 write new buf t:1 f:0 0000000000E8DA80, pos 0000000000E8DA80, size: 460 file: 0, size: 0
2016/03/01 16:35:36 [debug] 32462#0: *1 http write filter: l:0 f:0 s:460
2016/03/01 16:35:36 [debug] 32462#0: *1 lua sending last buf of the response body
2016/03/01 16:35:36 [debug] 32462#0: *1 http output filter "/xxx"
2016/03/01 16:35:36 [debug] 32462#0: *1 http copy filter: "/xxx"
2016/03/01 16:35:36 [debug] 32462#0: *1 lua capture body filter, uri "/xxx"
2016/03/01 16:35:36 [debug] 32462#0: *1 http postpone filter "/xxx" 00007FFFE0ECB970
2016/03/01 16:35:36 [debug] 32462#0: *1 http chunk: 0
2016/03/01 16:35:36 [debug] 32462#0: *1 write old buf t:1 f:0 0000000000E8DA80, pos 0000000000E8DA80, size: 460 file: 0, size: 0
2016/03/01 16:35:36 [debug] 32462#0: *1 write new buf t:0 f:0 0000000000000000, pos 00000000004F811A, size: 5 file: 0, size: 0
2016/03/01 16:35:36 [debug] 32462#0: *1 http write filter: l:1 f:0 s:465
2016/03/01 16:35:36 [debug] 32462#0: *1 http write filter limit 0
2016/03/01 16:35:36 [debug] 32462#0: *1 writev: 465 of 465
2016/03/01 16:35:36 [debug] 32462#0: *1 http write filter 0000000000000000
2016/03/01 16:35:36 [debug] 32462#0: *1 http copy filter: 0 "/xxx"
2016/03/01 16:35:36 [error] 32462#0: *1 attempt to set ngx.status after sending out response headers while sending to client, client: xx.xx.xx.xx, server: x.sina.cn, request: "GET /xxx HTTP/1.1", host: "xx.sina.cn:9110"

一看果然是在響應(yīng)發(fā)出后報(bào)的錯(cuò)，但日志沒有反應(yīng)出報(bào)錯(cuò)的具體位置。沒辦法，我只能通過“二分步進(jìn)法”，打一堆日志來跟進(jìn)，人肉找出來到底什么地方報(bào)的錯(cuò)。

ngx_log(ngx.ERR, "-------------=====1=======--------------------->")
ngx.exit(ngx.ERROR)

最后跟到這樣一處邏輯：

if response:response() then ngx.eof() end

請求正常完成后，response:response() 執(zhí)行結(jié)果確定是true，問題一定出在 ngx.eof()，
我的本意在于如果在routerShutdown階段（Vanilla請求處理的第二個(gè)階段）請求完成響應(yīng)，則后面的幾個(gè)階段就不再執(zhí)行，直接結(jié)束當(dāng)前請求。查閱文檔發(fā)現(xiàn) ngx.eof() 只是顯式指定了響應(yīng)流輸出結(jié)束，后面的代碼邏輯會(huì)在服務(wù)端繼續(xù)執(zhí)行。而我期望的當(dāng)前請求直接終止，不應(yīng)該使用 ngx.eof() 而是 ngx.exit()。下面我們細(xì)節(jié)來認(rèn)識下這兩個(gè)API。

雖然在OpenResty ngx-lua 模塊文檔中這兩個(gè)API文檔位置緊鄰，但用法和功能方面卻截然不同。

用法： ngx.exit(status)
執(zhí)行上下文： rewrite_by_lua, access_by_lua, content_by_lua, header_filter_by_lua, ngx.timer., balancer_by_lua, ssl_certificate_by_lua*
ngx.exit()的使用相對簡單些：

當(dāng)傳入的status >= 200（200即為ngx.HTTP_OK），ngx.exit() 會(huì)中斷當(dāng)前請求，并將傳入的狀態(tài)碼（status）返回給nginx。

當(dāng)傳入的status == 0（0即為ngx.OK）則 ngx.exit() 會(huì)中斷當(dāng)前執(zhí)行的phrase（ngx-lua模塊處理請求的階段，如content_by_lua*），進(jìn)而繼續(xù)執(zhí)行下面的phrase。

對于 ngx.exit() 需要進(jìn)一步注意的是參數(shù)status的使用，status可以傳入ngx-lua所定義的所有的HTTP狀態(tài)碼常量（如：ngx.HTTP_OK、ngx.HTTP_GONE、ngx.HTTP_INTERNAL_SERVER_ERROR等）和兩個(gè)ngx-lua模塊內(nèi)核常量（只支持NGX_OK和NGX_ERROR這兩個(gè)，如果傳入其他的如ngx.AGAIN等則進(jìn)程hang住）。

文檔中推薦的 ngx.exit() 最佳實(shí)踐是同 return 語句組合使用，目的在于增強(qiáng)請求被終止的語義（return ngx.exit(...)）。

用法： ok, err = ngx.eof()
執(zhí)行上下文： rewrite_by_lua, access_by_lua, content_by_lua*
ngx.eof 除了前面所說的顯式指定了響應(yīng)流輸出的結(jié)束，后面的邏輯繼續(xù)在服務(wù)端執(zhí)行外，還需要注意以下幾點(diǎn)：

當(dāng)你禁用了HTTP1.1的keep-alive特性后可以通過調(diào)用 ngx.eof（） 來使客戶端主動(dòng)斷開連接，這個(gè)技巧可以用來做一些back-ground jobs 而不需要HTTP客戶端等待連接（不過文檔推薦的back-ground jobs的處理方式是 ngx.timer.at API，詳情請看文檔說明）。

當(dāng)你創(chuàng)建子請求來請求在其他 location 配置的上游模塊時(shí)，你應(yīng)該配置這些上游模塊來忽略客戶端連接的中斷，如果默認(rèn)不是忽略的話。例如默認(rèn)的標(biāo)準(zhǔn) ngx_http_proxy_module 模塊會(huì)在客戶端斷開連接后立即同時(shí)終止子請求和主請求，所以在模塊 ngx_http_proxy_module 將proxy_ignore_client_abort 設(shè)置為開啟（proxy_ignore_client_abort on;）就十分重要。

自 v0.8.3 起， ngx.eof（） 執(zhí)行成功返回1，失敗則返回 nil 和錯(cuò)誤描述信息。

實(shí)踐發(fā)現(xiàn) ngx.exit() 和 ngx.eof（） 本質(zhì)區(qū)別在于ngx.exit()作用在于中斷當(dāng)前操作，不管是ngx-lua模塊請求處理的當(dāng)前階段還是整個(gè)請求，而 ngx.eof（） 只是結(jié)束響應(yīng)流的輸出，中斷HTTP連接，后面的代碼邏輯還會(huì)繼續(xù)在服務(wù)端執(zhí)行，而且 ngx.eof（）支持運(yùn)行的上下文比 ngx.exit（）少太多， ngx.eof（） 有返回值， ngx.exit（）則沒有，因?yàn)檎埱笠呀?jīng)結(jié)束。

其實(shí)這是一個(gè)不大不小的bug，說它小，因?yàn)楹髞砦以谖臋n中對ngx.status的描述中發(fā)現(xiàn)這么一句 Setting ngx.status after the response header is sent out has no effect but leaving an error message in your nginx"s error log file 說明，也就是試圖在響應(yīng)頭發(fā)出后更改ngx.status會(huì)在錯(cuò)誤日志中記錄一條 [error] 但是這個(gè)錯(cuò)誤對本次請求的響應(yīng)沒有影響；說它大，如果沒有仔細(xì)查出來這個(gè)沒有影響，那一切都是未知，很可能給系統(tǒng)埋下一個(gè)未知的坑，不知道哪天就會(huì)爆出來坑你一下，關(guān)鍵的一點(diǎn)還是對API的理解。OpenResty的文檔是我見過開源項(xiàng)目中寫的比較好的，雖然是英文。還是值得仔細(xì)研習(xí)。