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

2024年4月11日 228次阅读 来源: iDev_周晶

事由

我们基于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

逻辑上肉眼没看出什么问题，只能通过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。

ngx.eof() 与 ngx.exit()

虽然在OpenResty ngx-lua 模块文档中这两个API文档位置紧邻，但用法和功能方面却截然不同。

ngx.exit

用法： 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(...)）。

ngx.eof

用法： 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和debug中成长

其实这是一个不大不小的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的文档是我见过开源项目中写的比较好的，虽然是英文。还是值得仔细研习。

    原文作者：iDev_周晶
    原文地址: https://segmentfault.com/a/1190000004534300
    本文转自网络文章，转载此文章仅为分享知识，如有侵权，请联系博主进行删除。
点赞