由一条OpenResty Error log谈谈ngx.exit与ngx.eof的区别

摘要：一看果然是在响应发出后报的错，但日志没有反应出报错的具体位置。而我期望的当前请求直接终止，不应该使用而是。自起，执行成功返回，失败则返回和错误描述信息。

我们基于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的文档是我见过开源项目中写的比较好的，虽然是英文。还是值得仔细研习。