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

我們基于Vanilla開發了一個類似于一個網關的流量分發服務，在原來的業務線上對不同的業務使用不同的后端（PHP、Python、Lua...）進行處理，最近在緊鑼密鼓的測試（當然這里咱們主要看問題），在掃蕩日志的過程中發現有這樣的一條 [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"

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

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

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

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

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

邏輯上肉眼沒看出什么問題，只能通過debug來解決。到底哪行報出來的錯誤呢？在公司開發機上添加 --with-debug 參數重新編譯了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"

一看果然是在響應發出后報的錯，但日志沒有反應出報錯的具體位置。沒辦法，我只能通過“二分步進法”，打一堆日志來跟進，人肉找出來到底什么地方報的錯。

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

最后跟到這樣一處邏輯：

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

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

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

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

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

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

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

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

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

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

當你創建子請求來請求在其他 location 配置的上游模塊時，你應該配置這些上游模塊來忽略客戶端連接的中斷，如果默認不是忽略的話。例如默認的標準 ngx_http_proxy_module 模塊會在客戶端斷開連接后立即同時終止子請求和主請求，所以在模塊 ngx_http_proxy_module 將proxy_ignore_client_abort 設置為開啟（proxy_ignore_client_abort on;）就十分重要。

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

實踐發現 ngx.exit() 和 ngx.eof（） 本質區別在于ngx.exit()作用在于中斷當前操作，不管是ngx-lua模塊請求處理的當前階段還是整個請求，而 ngx.eof（） 只是結束響應流的輸出，中斷HTTP連接，后面的代碼邏輯還會繼續在服務端執行，而且 ngx.eof（）支持運行的上下文比 ngx.exit（）少太多， ngx.eof（） 有返回值， ngx.exit（）則沒有，因為請求已經結束。

其實這是一個不大不小的bug，說它小，因為后來我在文檔中對ngx.status的描述中發現這么一句 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 說明，也就是試圖在響應頭發出后更改ngx.status會在錯誤日志中記錄一條 [error] 但是這個錯誤對本次請求的響應沒有影響；說它大，如果沒有仔細查出來這個沒有影響，那一切都是未知，很可能給系統埋下一個未知的坑，不知道哪天就會爆出來坑你一下，關鍵的一點還是對API的理解。OpenResty的文檔是我見過開源項目中寫的比較好的，雖然是英文。還是值得仔細研習。