ngx.sleep 残留的问题

liou.wang · 2017-04-21T10:04:08+00:00

直接 require "resty.core.regex" 即可。比如在 init_by_lua_block 里面加一&#x8...

ngx.sleep 残留的问题

liou.wang

现象：在lua脚本中拉起ngx.sleep后，由于异常触发ngx走关链流程，清掉运行lua的协程上下文，但是ngx.sleep来起的事件没有及时清理，残留在ngx中继续运行。

有没有大家了解这个解决方法的？

yuansheng_335c

> 但是ngx.sleep来起的事件没有及时清理

请提供一个明确的例子，你这里说的有点模糊。

2017-04-21 10:04 GMT+08:00 L Wang <liou...@gmail.com>:

现象：在lua脚本中拉起ngx.sleep后，由于异常触发ngx走关链流程，清掉运行lua的协程上下文，但是ngx.sleep来起的事件没有及时清理，残留在ngx中继续运行。
有没有大家了解这个解决方法的？

--

membphis

liou.wang

首先描述一下场景流程：

1，客户端发起连接，进入NGX处理流程

2，在CONTENT PHASE，进入lua脚本（简单一点：比如content_by_lua_file）

3，在lua脚本中处理业务逻辑时，通过ngx.sleep发起ngx timer事件

4，回到NGX处理流程，此时，客户端主动发起断链，触发NGX走关链流程，close request, close connection

5，发现：此前触发的ngx timer事件并没有被清除，而是在请求生命周期结束后，依然因超时而被触发执行。

下面是一段以请求（request）的生命周期为主线，抓的一段我们的日志：

2017-04-16 18:19:42.252][tid 3417802][co 0x7f99c99c6f18] [DEBUG] ngx_http_create_request: r:0x7f99ca2a4bf0, c:0x7f993a558a70, pool:0x7f99ca2a4ba0, ctx 0x7f99ca2a54e8

[2017-04-16 18:19:42.252][tid 3417802][co 0x7f99c99c6f18] [DEBUG] ngx_http_lua_content_by_chunk: r:0x7f99ca2a4bf0, vm:0x41a1b378, ctx:0x7f99ca2ba280 => co:0x40c19f40

[2017-04-16 18:19:42.252][tid 3417802][co 0x7f99c99c6f18] [DEBUG] ngx_http_lua_content_by_chunk: r:0x7f99ca2a4bf0, vm:0x41a1b378, ctx:0x7f99ca2ba280 => run thread

[2017-04-16 18:19:44.453][tid 3417802][co 0x7f99c99c6f18] [DEBUG] ngx_http_lua_ngx_sleep: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2ba280, cur:0x7f99ca2ba2a8, cleanup:0x5e0afe(0x7f99ca2a4bf0), ev:0x7f99ca2ba2f8

[2017-04-16 18:19:44.453][tid 3417802][co 0x7f99c99c6f18] [DEBUG] ngx_http_lua_ngx_sleep: r:0x7f99ca2a4bf0, delay:546, uri:/flv/100/109/o0018qvarf5.mp4, ev:0x7f99ca2ba2f8

[2017-04-16 18:19:44.453][tid 3417802][co 0x7f99c99c6f18] [DEBUG] ngx_http_lua_content_by_chunk: r:0x7f99ca2a4bf0, vm:0x41a1b378, ctx:0x7f99ca2ba280 => run back, rc:-2

[2017-04-16 18:19:44.453][tid 3417802][co 0x7f99c99c6f18] [DEBUG] ngx_http_lua_content_by_chunk: r:0x7f99ca2a4bf0, vm:0x41a1b378, ctx:0x7f99ca2ba280 => AGAIN, run posted

[2017-04-16 18:19:44.453][tid 3417802][co 0x7f99c99c6f18] [DEBUG] ngx_http_close_request: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2a54e8, count:2, blocked:0

[2017-04-16 18:19:45.027][tid 3417802][co 0x7f9936232d00] [DEBUG] ngx_http_lua_sleep_handler: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2ba280, r->cleanup:0x7f99ca2a5b80

[2017-04-16 18:19:45.027][tid 3417802][co 0x7f9936232d00] [DEBUG] ngx_http_lua_sleep_handler: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2ba280, cur:0x7f99ca2ba2a8, r->cleanup:0x7f99ca2a5b80

[2017-04-16 18:19:45.730][tid 3417802][co 0x7f9936232d00] [DEBUG] ngx_http_lua_ngx_sleep: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2ba280, cur:0x7f99ca2ba2a8, cleanup:0x5e0afe(0x7f99ca2a4bf0), ev:0x7f99ca2ba2f8

[2017-04-16 18:19:45.730][tid 3417802][co 0x7f9936232d00] [DEBUG] ngx_http_lua_ngx_sleep: r:0x7f99ca2a4bf0, delay:270, uri:/flv/100/109/o0018qvarf5.mp4, ev:0x7f99ca2ba2f8

[2017-04-16 18:19:45.730][tid 3417802][co 0x7f9936232d00] [DEBUG] ngx_http_lua_sleep_handler: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2ba280, cur:(nil), r->cleanup:0x7f99ca2a5b80

[2017-04-16 18:19:46.038][tid 3417802][co 0x7f99362364f0] [DEBUG] ngx_http_lua_sleep_handler: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2ba280, r->cleanup:0x7f99ca2a5b80

[2017-04-16 18:19:46.038][tid 3417802][co 0x7f99362364f0] [DEBUG] ngx_http_lua_sleep_handler: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2ba280, cur:0x7f99ca2ba2a8, r->cleanup:0x7f99ca2a5b80

[2017-04-16 18:19:46.411][tid 3417802][co 0x7f99362364f0] [DEBUG] ngx_http_lua_ngx_sleep: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2ba280, cur:0x7f99ca2ba2a8, cleanup:0x5e0afe(0x7f99ca2a4bf0), ev:0x7f99ca2ba2f8

[2017-04-16 18:19:46.411][tid 3417802][co 0x7f99362364f0] [DEBUG] ngx_http_lua_ngx_sleep: r:0x7f99ca2a4bf0, delay:588, uri:/flv/100/109/o0018qvarf5.mp4, ev:0x7f99ca2ba2f8

[2017-04-16 18:19:46.411][tid 3417802][co 0x7f99362364f0] [DEBUG] ngx_http_lua_sleep_handler: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2ba280, cur:(nil), r->cleanup:0x7f99ca2a5b80

[2017-04-16 18:19:47.043][tid 3417802][co 0x7f993623ada8] [DEBUG] ngx_http_lua_sleep_handler: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2ba280, r->cleanup:0x7f99ca2a5b80

[2017-04-16 18:19:47.043][tid 3417802][co 0x7f993623ada8] [DEBUG] ngx_http_lua_sleep_handler: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2ba280, cur:0x7f99ca2ba2a8, r->cleanup:0x7f99ca2a5b80

[2017-04-16 18:19:48.123][tid 3417802][co 0x7f9936232d00] [DEBUG] ngx_http_lua_finalize_request: r:0x7f99ca2a4bf0, rc:499

[2017-04-16 18:19:48.123][tid 3417802][co 0x7f9936232d00] [DEBUG] ngx_http_lua_finalize_request: r:0x7f99ca2a4bf0, ctx:0x7f99ca2ba280, cur:0x7f99ca2ba2a8 => cleanup pending

[2017-04-16 18:19:48.123][tid 3417802][co 0x7f9936232d00] [DEBUG] ngx_http_lua_finalize_request: r:0x7f99ca2a4bf0, ctx:0x7f99ca2ba280, c:0x7f993a558a70 => fin req

[2017-04-16 18:19:48.123][tid 3417802][co 0x7f9936232d00] [DEBUG] ngx_http_close_request: r:0x7f99ca2a4bf0, c:0x7f993a558a70, ctx:0x7f99ca2a54e8, count:1, blocked:0

[2017-04-16 18:19:48.123][tid 3417802][co 0x7f9936232d00] [DEBUG] ngx_http_free_request: r:0x7f99ca2a4bf0, pool:0x7f99ca2a4ba0, ctx:0x7f99ca2a54e8, cleanup:(nil)

NGX流程在检测到客户端断链后，第一次尝试关闭请求，发现count = 2，放弃。

进入LUA脚本执行，ngx.sleep被再次调用，ngx_http_lua_ngx_sleep注册cleanup清理函数（ngx_http_lua_sleep_cleanup）

回到NGX流程，进入ngx_http_lua_finalize_request，发现499码，此时，请求的count = 1，开始关闭请求、关闭连接，在清理现场时，发现请求（r）的清理函数堆栈（r->cleanup）为空。

问题出在关闭请求时，发现清理函数堆栈为空

Sleep时已经主动注册过自己的清理函数到LUA协程的上下文中。进一步跟踪流程发现在ngx_http_lua_run_thread中，resume后的处理分支：case LUA_YIELD => case NGX_HTTP_LUA_USER_CORO_NOP处，当前协程的上下文被强行清除（ctx->cur_co_ctx = NULL），而此时sleep拉起的事件在等待超时触发，此后进入NGX关断流程时，该事件残留在系统中被再次执行。

我们的一个修补方式是，在当前协程上下文被强行清除前，主动执行一次pending的清理：

case NGX_HTTP_LUA_USER_CORO_NOP:

dd("hit! it is the API yield");

ngx_http_lua_assert(lua_gettop(ctx->cur_co_ctx->co) == 0);

ngx_http_lua_cleanup_pending_operation(ctx->cur_co_ctx);/*patch*/

ctx->cur_co_ctx = NULL;

return NGX_AGAIN;

我们的问题是：

1，请求与连接已关闭时，为什么没有将与之相关的所有事件清理干净？这是有基于某些特别的考虑，还是确实是一个BUG？

2，上面这样的修补方式是否正确？我们对修补点不是有十分的把握，但修补后确实没有再发现sleep事件残留。

On Saturday, April 22, 2017 at 12:49:04 AM UTC+8, Yuansheng wrote:

> 但是ngx.sleep来起的事件没有及时清理

请提供一个明确的例子，你这里说的有点模糊。

2017-04-21 10:04 GMT+08:00 L Wang <liou...@gmail.com>:
现象：在lua脚本中拉起ngx.sleep后，由于异常触发ngx走关链流程，清掉运行lua的协程上下文，但是ngx.sleep来起的事件没有及时清理，残留在ngx中继续运行。
有没有大家了解这个解决方法的？

--

--

membphis

xutimon

原因其实是因为timer在实现上是采用另外一个线程执行的,和你发起的请求毫无关系,上下文也是不会存在

解决方法为,注册on_abort事件处理用户主动关闭连接情况.

从请求的角度来说,主动关闭和超时这两种情况都需要你特殊处理来填坑的哦,亲

--注册一个回调函数在客户端主动断开后执行的方法,需要lua_check_client_abort状态为on

syntax: ok,err = ngx.on_abort(func)

context: rewrite_by_lua,access_by_lua,content_by_lua

--设置ngx.on_abort是否生效

syntax: lua_check_client_abort on|off

default: lua_check_client_abort off

在 2017年4月21日星期五 UTC+8上午10:04:08，L Wang写道：

现象：在lua脚本中拉起ngx.sleep后，由于异常触发ngx走关链流程，清掉运行lua的协程上下文，但是ngx.sleep来起的事件没有及时清理，残留在ngx中继续运行。
有没有大家了解这个解决方法的？

hadalsyang

timer 和本请求脱离关系了

在 2017年4月21日星期五 UTC+8上午10:04:08，L Wang写道：

现象：在lua脚本中拉起ngx.sleep后，由于异常触发ngx走关链流程，清掉运行lua的协程上下文，但是ngx.sleep来起的事件没有及时清理，残留在ngx中继续运行。
有没有大家了解这个解决方法的？