499 有一定几率导致 Nginx worker crash ( signal 11 )

timebug.info

1. 项目依赖的组件版本号

V_PCRE=8.34
V_ZLIB=1.2.8
V_NGINX=1.4.6
V_LUAJIT=2.0.3
V_OPENSSL=1.0.1f
V_LUA_CJSON=2.1.0
V_LUA_BITOP=1.0.2
V_NGX_DEVEL_KIT=0.2.19
V_NGX_LUA_MODULE=0.9.6

2. Nginx error_log & dmesg

error_log:

2014/04/03 06:18:31 [alert] 3487518#0: worker process 4012652 exited on signal 11

dmesg:

Apr 3 06:18:31 localhost kernel: nginx[4012652]: segfault at 1a761f0 ip 000000000047187c sp 00007fff1202ccb0 error 4 in nginx.20140313[400000+2ca000]

通过 addr2line 工具分析得到如下信息：

[vagrant@centos test]$ addr2line -e nginx.20140313 000000000047187c

src/http/ngx_http_request.c:2388

3. coredump 帧信息

(gdb) bt

#0 ngx_http_terminate_request (r=0x3f19ec0, rc=499) at src/http/ngx_http_request.c:2384

#1 0x0000000000477d87 in ngx_http_finalize_request (r=0x3f19ec0, rc=499) at src/http/ngx_http_request.c:2221

#2 0x00000000004cceae in ngx_http_lua_finalize_request (r=<value optimized out>, rc=<value optimized out>)

at lua-nginx-module-0.9.4/src/ngx_http_lua_util.c:3492

#3 0x00000000004ccf3d in ngx_http_lua_rd_check_broken_connection (r=0x3f19ec0)

at lua-nginx-module-0.9.4/src/ngx_http_lua_util.c:3357

#4 0x0000000000474e89 in ngx_http_request_handler (ev=0x7f639c0c72a8) at src/http/ngx_http_request.c:2110

#5 0x000000000045c689 in ngx_event_process_posted (cycle=0x19e6120, posted=0x909428) at src/event/ngx_event_posted.c:40

#6 0x000000000045c4b3 in ngx_process_events_and_timers (cycle=0x19e6120) at src/event/ngx_event.c:276

#7 0x0000000000463270 in ngx_worker_process_cycle (cycle=0x19e6120, data="" optimized out>)

at src/os/unix/ngx_process_cycle.c:807

#8 0x00000000004619fc in ngx_spawn_process (cycle=0x19e6120, proc=0x46317a <ngx_worker_process_cycle>, data="">

name=0x6313f3 "worker process", respawn=-3) at src/os/unix/ngx_process.c:198

#9 0x00000000004626c8 in ngx_start_worker_processes (cycle=0x19e6120, n=4, type=-3) at src/os/unix/ngx_process_cycle.c:362

#10 0x00000000004638d4 in ngx_master_process_cycle (cycle=0x19e6120) at src/os/unix/ngx_process_cycle.c:136

#11 0x0000000000446baa in main (argc=<value optimized out>, argv=<value optimized out>) at src/core/nginx.c:412

4. 其他说明

特别地，nginx.conf 中配置了 lua_check_client_abort on; 每次 coredump 分析， rc 始终值始终为 499。

另外，当将 accept_mutex 设置为 off 时，这个 crash 频率会提高很多，默认 on 情况下，一天只会遇到几次。

其他因为业务方面的 Lua 代码比较多，这里就不一一贴出来了，个人感觉应该跟 Lua 层面逻辑代码关系不大。其中比较特殊的是使用了 lua-resty-shcache, lua-resty-lock 等类库，以及在 log_by_lua 阶段申请了一个 0 延时的 timer.at 事件利用 cosocket 向某个统计服务发送一些实时统计信息的操作。

agentzh

Hello!

2014-04-02 19:29 GMT-07:00 Monkey Zhang:
> V_NGINX=1.4.6

推荐使用最新的 nginx 主线版 1.5.x. 特别地，推荐使用 openresty 里自带的 nginx（因为包含了尚未合入官方
nginx 的重要的 bugfix）。

> V_LUA_BITOP=1.0.2

LuaJIT 自带了 bit 扩展，所以这个不需要。见

    http://luajit.org/extensions.html

> V_NGX_LUA_MODULE=0.9.6
>

这里声称使用的是 0.9.6，但你下面给出的 gdb backtrace 里指向的路径却是 lua-nginx-module-0.9.4.
你究竟使用的是哪个版本的 ngx_lua?

> 3. coredump 帧信息
>
> (gdb) bt
> #0  ngx_http_terminate_request (r=0x3f19ec0, rc=499) at
> src/http/ngx_http_request.c:2384

这个崩溃位置非常奇怪，我从未见过 nginx 崩溃在这个位置上。说它奇怪是因为 request 的 cleanup
结构体（ngx_http_cleanup_t
类型）一般都是在请求的内存池里分配的，所以在这个上下文里是不可能被提前释放掉的，即不可能为非法内存区域的。

你的 nginx 里是否使用了某些特别的第三方 nginx C 模块？请给出 nginx -V
命令的输出。我现在很怀疑是因为你使用的某个第三方 nginx C 模块而导致的问题，看起来和 ngx_lua 和 nginx
核心并没有什么关系。

另外，请在 gdb 里使用 bt full 命令和 disas 命令以得到崩溃位置上更详尽的信息（最重要的是 frame 0 哈）。

> 其他因为业务方面的 Lua 代码比较多，这里就不一一贴出来了，个人感觉应该跟 Lua 层面逻辑代码关系不大。其中比较特殊的是使用了
> lua-resty-shcache, lua-resty-lock 等类库，以及在 log_by_lua 阶段申请了一个 0 延时的 timer.at
> 事件利用 cosocket 向某个统计服务发送一些实时统计信息的操作。
>

我们公司的生产环境使用你提到的这些库和功能已经很久了，从没有遇到过这种问题 :)

最好你能提供一个最小化的完整的用例，以便我可以在我本地比较可靠地复现你看到的问题。

Regards,
-agentzh

timebug.info

> 这里声称使用的是 0.9.6，但你下面给出的 gdb backtrace 里指向的路径却是 lua-nginx-module-0.9.4.
> 你究竟使用的是哪个版本的 ngx_lua?

是 0.9.4，这里写错了。

> 你的 nginx 里是否使用了某些特别的第三方 nginx C 模块？请给出 nginx -V
> 命令的输出。我现在很怀疑是因为你使用的某个第三方 nginx C 模块而导致的问题，看起来和 ngx_lua 和 nginx
> 核心并没有什么关系。

configure arguments: --with-http_ssl_module --with-openssl=deps/openssl-1.0.1f --with-http_stub_status_module --with-pcre=deps/pcre-8.34 --with-zlib=deps/zlib-1.2.8 --add-module=deps/ngx_devel_kit-0.2.19 --add-module=deps/lua-nginx-module-0.9.4 --add-module=addons/ngx_http_redis --add-module=addons/nginx-eval-module

其中 ngx_http_redis 来自 http://wiki.nginx.org/HttpRedis, nginx-eval-module 来自 https://github.com/vkholodkov/nginx-eval-module

> 另外，请在 gdb 里使用 bt full 命令和 disas 命令以得到崩溃位置上更详尽的信息（最重要的是 frame 0 哈）。

(gdb) bt full

#0 ngx_http_terminate_request (r=0x3f19ec0, rc=499) at src/http/ngx_http_request.c:2384

cln = 0x3f1ade8

mr = 0x3f19ec0

e = <value optimized out>

#1 0x0000000000477d87 in ngx_http_finalize_request (r=0x3f19ec0, rc=499) at src/http/ngx_http_request.c:2221

c = 0x7f639c75c750

pr = <value optimized out>

#2 0x00000000004cceae in ngx_http_lua_finalize_request (r=<value optimized out>, rc=<value optimized out>)

at deps/lua-nginx-module-0.9.4/src/ngx_http_lua_util.c:3492

No locals.

#3 0x00000000004ccf3d in ngx_http_lua_rd_check_broken_connection (r=0x3f19ec0)

at deps/lua-nginx-module-0.9.4/src/ngx_http_lua_util.c:3357

rc = 499

rev = <value optimized out>

ctx = 0x1bb0b50

#4 0x0000000000474e89 in ngx_http_request_handler (ev=0x7f639c0c72a8) at src/http/ngx_http_request.c:2110

c = 0x7f639c75c750

r = 0x3f19ec0

ctx = <value optimized out>

#5 0x000000000045c689 in ngx_event_process_posted (cycle=0x19e6120, posted=0x909428) at src/event/ngx_event_posted.c:40

ev = 0x7f639c0c72a8

#6 0x000000000045c4b3 in ngx_process_events_and_timers (cycle=0x19e6120) at src/event/ngx_event.c:276

flags = 3

timer = <value optimized out>

delta = 0

#7 0x0000000000463270 in ngx_worker_process_cycle (cycle=0x19e6120, data="" optimized out>)

at src/os/unix/ngx_process_cycle.c:807

worker = <value optimized out>

i = <value optimized out>

c = <value optimized out>

#8 0x00000000004619fc in ngx_spawn_process (cycle=0x19e6120, proc=0x46317a <ngx_worker_process_cycle>, data="">

name=0x6313f3 "worker process", respawn=-3) at src/os/unix/ngx_process.c:198

on = 1

pid = 0

---Type <return> to continue, or q <return> to quit---

s = 0

#9 0x00000000004626c8 in ngx_start_worker_processes (cycle=0x19e6120, n=4, type=-3) at src/os/unix/ngx_process_cycle.c:362

i = <value optimized out>

ch = {command = 1, pid = -1041123563, slot = 0, fd = 11}

#10 0x00000000004638d4 in ngx_master_process_cycle (cycle=0x19e6120) at src/os/unix/ngx_process_cycle.c:136

title = 0x1a7c33c "master process /usr/local/nginx/sbin/nginx -c /usr/local/nginx/conf/nginx.conf"

p = <value optimized out>

size = 91

i = 3

n = <value optimized out>

sigio = <value optimized out>

set = {__val = {0 <repeats 16 times>}}

itv = {it_interval = {tv_sec = 27161555, tv_usec = 0}, it_value = {tv_sec = 0, tv_usec = 0}}

live = <value optimized out>

delay = <value optimized out>

ls = <value optimized out>

ccf = 0x19e7098

#11 0x0000000000446baa in main (argc=<value optimized out>, argv=<value optimized out>) at src/core/nginx.c:412

i = <value optimized out>

log = 0x8fffe0

cycle = 0x19e6120

init_cycle = {conf_ctx = 0x0, pool = 0x19e5900, log = 0x8fffe0, new_log = {log_level = 0, file = 0x0,

connection = 0, handler = 0, data = "" action = "" files = 0x0, free_connections = 0x0,

free_connection_n = 0, reusable_connections_queue = {prev = 0x0, next = 0x0}, listening = {elts = 0x0, nelts = 0,

size = 0, nalloc = 0, pool = 0x0}, paths = {elts = 0x0, nelts = 0, size = 0, nalloc = 0, pool = 0x0},

open_files = {last = 0x0, part = {elts = 0x0, nelts = 0, next = 0x0}, size = 0, nalloc = 0, pool = 0x0},

shared_memory = {last = 0x0, part = {elts = 0x0, nelts = 0, next = 0x0}, size = 0, nalloc = 0, pool = 0x0},

connection_n = 0, files_n = 0, connections = 0x0, read_events = 0x0, write_events = 0x0, old_cycle = 0x0,

conf_file = {len = 38, data = "" ""}, conf_param = {len = 0, data = "" conf_prefix = {len = 28,

data = "" ""}, prefix = {len = 23, data = "" "/usr/local/nginx/"}, lock_file = {

len = 0, data = "" hostname = {len = 0, data = "">

ccf = <value optimized out>

(gdb) disas

Dump of assembler code for function ngx_http_terminate_request:

0x00000000004757b4 <+0>: push %r13

0x00000000004757b6 <+2>: push %r12

0x00000000004757b8 <+4>: push %rbp

0x00000000004757b9 <+5>: push %rbx

0x00000000004757ba <+6>: sub $0x8,%rsp

0x00000000004757be <+10>: mov %rdi,%r12

0x00000000004757c1 <+13>: mov %rsi,%r13

0x00000000004757c4 <+16>: mov 0x3a8(%rdi),%rbp

0x00000000004757cb <+23>: mov 0x8(%rdi),%rax

0x00000000004757cf <+27>: mov 0x50(%rax),%rsi

0x00000000004757d3 <+31>: mov (%rsi),%rax

0x00000000004757d6 <+34>: test $0x1,%ah

0x00000000004757d9 <+37>: je 0x4757fc <ngx_http_terminate_request+72>

0x00000000004757db <+39>: movzbl 0x441(%rbp),%r8d

0x00000000004757e3 <+47>: mov $0x634628,%ecx

0x00000000004757e8 <+52>: mov $0x0,%edx

0x00000000004757ed <+57>: mov $0x8,%edi

0x00000000004757f2 <+62>: mov $0x0,%eax

0x00000000004757f7 <+67>: callq 0x44717c <ngx_log_error_core>

0x00000000004757fc <+72>: test %r13,%r13

0x00000000004757ff <+75>: jle 0x47581d <ngx_http_terminate_request+105>

0x0000000000475801 <+77>: cmpq $0x0,0x208(%rbp)

0x0000000000475809 <+85>: je 0x475816 <ngx_http_terminate_request+98>

0x000000000047580b <+87>: mov 0x8(%rbp),%rax

0x000000000047580f <+91>: cmpq $0x0,0x48(%rax)

0x0000000000475814 <+96>: jne 0x47581d <ngx_http_terminate_request+105>

0x0000000000475816 <+98>: mov %r13,0x208(%rbp)

0x000000000047581d <+105>: mov 0x438(%rbp),%rbx

0x0000000000475824 <+112>: movq $0x0,0x438(%rbp)

0x000000000047582f <+123>: test %rbx,%rbx

0x0000000000475832 <+126>: je 0x47584b <ngx_http_terminate_request+151>

=> 0x0000000000475834 <+128>: mov (%rbx),%rax

0x0000000000475837 <+131>: test %rax,%rax

---Type <return> to continue, or q <return> to quit---

0x000000000047583a <+134>: je 0x475842 <ngx_http_terminate_request+142>

0x000000000047583c <+136>: mov 0x8(%rbx),%rdi

0x0000000000475840 <+140>: callq *%rax

0x0000000000475842 <+142>: mov 0x10(%rbx),%rbx

0x0000000000475846 <+146>: test %rbx,%rbx

0x0000000000475849 <+149>: jne 0x475834 <ngx_http_terminate_request+128>

0x000000000047584b <+151>: mov 0x8(%r12),%rax

0x0000000000475850 <+156>: mov 0x50(%rax),%rsi

0x0000000000475854 <+160>: mov (%rsi),%rax

0x0000000000475857 <+163>: test $0x1,%ah

0x000000000047585a <+166>: je 0x475885 <ngx_http_terminate_request+209>

0x000000000047585c <+168>: movzbl 0x442(%rbp),%r9d

0x0000000000475864 <+176>: movzbl 0x441(%rbp),%r8d

0x000000000047586c <+184>: mov $0x634648,%ecx

0x0000000000475871 <+189>: mov $0x0,%edx

0x0000000000475876 <+194>: mov $0x8,%edi

0x000000000047587b <+199>: mov $0x0,%eax

0x0000000000475880 <+204>: callq 0x44717c <ngx_log_error_core>

0x0000000000475885 <+209>: cmpq $0x0,0x38(%rbp)

0x000000000047588a <+214>: je 0x4758b9 <ngx_http_terminate_request+261>

0x000000000047588c <+216>: cmpb $0x0,0x442(%rbp)

0x0000000000475893 <+223>: jne 0x4758c4 <ngx_http_terminate_request+272>

0x0000000000475895 <+225>: movq $0x0,0x3c8(%rbp)

0x00000000004758a0 <+236>: movq $0x4758cf,0x38(%rbp)

0x00000000004758a8 <+244>: lea 0x4a8(%rbp),%rsi

0x00000000004758af <+251>: mov %rbp,%rdi

0x00000000004758b2 <+254>: callq 0x474caf <ngx_http_post_request>

0x00000000004758b7 <+259>: jmp 0x4758c4 <ngx_http_terminate_request+272>

0x00000000004758b9 <+261>: mov %r13,%rsi

0x00000000004758bc <+264>: mov %rbp,%rdi

0x00000000004758bf <+267>: callq 0x4755e7 <ngx_http_close_request>

0x00000000004758c4 <+272>: add $0x8,%rsp

0x00000000004758c8 <+276>: pop %rbx

0x00000000004758c9 <+277>: pop %rbp

---Type <return> to continue, or q <return> to quit---

0x00000000004758ca <+278>: pop %r12

0x00000000004758cc <+280>: pop %r13

0x00000000004758ce <+282>: retq

End of assembler dump.

在 2014年4月4日星期五UTC+8上午4时05分54秒，agentzh写道：

Hello!

2014-04-02 19:29 GMT-07:00 Monkey Zhang:
> V_NGINX=1.4.6

推荐使用最新的 nginx 主线版 1.5.x. 特别地，推荐使用 openresty 里自带的 nginx（因为包含了尚未合入官方
nginx 的重要的 bugfix）。

> V_LUA_BITOP=1.0.2

LuaJIT 自带了 bit 扩展，所以这个不需要。见

http://luajit.org/extensions.html

> V_NGX_LUA_MODULE=0.9.6
>

这里声称使用的是 0.9.6，但你下面给出的 gdb backtrace 里指向的路径却是 lua-nginx-module-0.9.4.
你究竟使用的是哪个版本的 ngx_lua?

> 3. coredump 帧信息
>
> (gdb) bt
> #0 ngx_http_terminate_request (r=0x3f19ec0, rc=499) at
> src/http/ngx_http_request.c:2384

这个崩溃位置非常奇怪，我从未见过 nginx 崩溃在这个位置上。说它奇怪是因为 request 的 cleanup
结构体（ngx_http_cleanup_t
类型）一般都是在请求的内存池里分配的，所以在这个上下文里是不可能被提前释放掉的，即不可能为非法内存区域的。

你的 nginx 里是否使用了某些特别的第三方 nginx C 模块？请给出 nginx -V
命令的输出。我现在很怀疑是因为你使用的某个第三方 nginx C 模块而导致的问题，看起来和 ngx_lua 和 nginx
核心并没有什么关系。

另外，请在 gdb 里使用 bt full 命令和 disas 命令以得到崩溃位置上更详尽的信息（最重要的是 frame 0 哈）。

> 其他因为业务方面的 Lua 代码比较多，这里就不一一贴出来了，个人感觉应该跟 Lua 层面逻辑代码关系不大。其中比较特殊的是使用了
> lua-resty-shcache, lua-resty-lock 等类库，以及在 log_by_lua 阶段申请了一个 0 延时的 timer.at
> 事件利用 cosocket 向某个统计服务发送一些实时统计信息的操作。
>

我们公司的生产环境使用你提到的这些库和功能已经很久了，从没有遇到过这种问题 :)

最好你能提供一个最小化的完整的用例，以便我可以在我本地比较可靠地复现你看到的问题。

Regards,
-agentzh

agentzh

Hello!

2014-04-03 21:01 GMT-07:00 Monkey Zhang:
>
> 是 0.9.4，这里写错了。
>

建议升级到最新版本。

> 其中 ngx_http_redis 来自 http://wiki.nginx.org/HttpRedis, nginx-eval-module 来自
> https://github.com/vkholodkov/nginx-eval-module
>

这个版本的 ngx_eval 已知会有内存问题，建议不要在生产上使用。（同时你注意到那个 git 仓库已经 3 年没有更新了吗？）

建议使用 ngx_lua 的 ngx.location.capture 替换掉 eval 配置指令。

Regards,
-agentzh