Issues with subrequests in Lua 5.1.4 #54

ghost · 2011-08-26T11:36:51Z

Hi,

When using Lua 5.1.4 to do subrequests (e.g. ngx.location.capture() -> memc_pass), after the first or second subrequest, I've found that that I've had a host of problems, including:

segfaulting
'attempt to call a nil value' errors
and (in versions around 2.0 - 2.1.7/8 of ngx_lua)
'attempt to yield across metamethod/C-call boundary' errors

As mentioned in another post, I've been doing a lot of hacking, and didn't do any checking without my code compiled-in. However, when I switched to LuaJIT, these issues went away.

I don't know how interested you are in supporting 5.1.4 since you're using JIT, but just in case you were, I thought I'd pass it on. I'm afraid I haven't got the time to look into it in any more depth myself right now.

Cheers,

Marcus.

agentzh · 2011-08-26T15:08:49Z

On Fri, Aug 26, 2011 at 7:36 PM, simpl
reply@reply.github.com
wrote:

When using Lua 5.1.4 to do subrequests (e.g. ngx.location.capture() -> memc_pass), after the first or second subrequest, I've found that that I've had a host of problems, including:

segfaulting

'attempt to call a nil value' errors

Can you provide a minimized standalone test case for these?

and (in versions around 2.0 - 2.1.7/8 of ngx_lua)

'attempt to yield across metamethod/C-call boundary' errors

This is a restriction in the standard Lua 5.1 interpreter because its
VM is not fully resumable while LuaJIT 2.0 is.

As mentioned in another post, I've been doing a lot of hacking, and didn't do any checking without my code compiled-in. However, when I switched to LuaJIT, these issues went away.

I don't know how interested you are in supporting 5.1.4 since you're using JIT,

We've been trying hard to support the standard Lua 5.1.4 interpreter :)

but just in case you were, I thought I'd pass it on. I'm afraid I haven't got the time to look into it in any more depth myself right now.

We definitely need more information for these issues :)

Thanks!
-agentzh

ghost · 2011-08-26T16:13:35Z

I've got a tight deadline at the moment, and don't really have the time to look into it again right now. When I'm a bit freer, I'll send you some more info.

agentzh · 2011-11-17T10:42:14Z

Any update on this issue?

ghost · 2011-11-17T10:55:33Z

Sorry, I'd forgotten about this - I've been very busy of late. I've been using LuaJIT recently, and haven't noticed these particular issues. When I'm less busy with stuff, I'll test out what I'm doing with 5.1 and the latest builds.

agentzh · 2012-04-19T04:46:42Z

Any updates on this issue?

sztanpet · 2012-06-23T19:57:28Z

seems I have a similar issue,
here is a backtrace for starters

#0  0x000000000052533e in luaH_next ()
#1  0x000000000051b51c in lua_next ()
#2  0x00000000004d67f0 in ngx_http_lua_calc_strlen_in_table (L=0x221ba20, arg_i=1, strict=0)
    at ../ngx_lua-0.5.0rc30/src/ngx_http_lua_output.c:253
#3  0x00000000004d626f in ngx_http_lua_ngx_echo (L=0x221ba20, newline=0)
    at ../ngx_lua-0.5.0rc30/src/ngx_http_lua_output.c:108
#4  0x00000000004d609f in ngx_http_lua_ngx_print (L=0x221ba20) at ../ngx_lua-0.5.0rc30/src/ngx_http_lua_output.c:24
#5  0x000000000051e429 in luaD_precall ()
#6  0x0000000000527a79 in luaV_execute ()
#7  0x000000000051dfc7 in luaD_rawrunprotected ()
#8  0x000000000051e190 in lua_resume ()
#9  0x00000000004e3406 in ngx_http_lua_run_thread (L=0x222e970, r=0x2224b60, ctx=0x2225ff0, nret=1)
    at ../ngx_lua-0.5.0rc30/src/ngx_http_lua_util.c:775
#10 0x00000000004e414a in ngx_http_lua_wev_handler (r=0x2224b60) at ../ngx_lua-0.5.0rc30/src/ngx_http_lua_util.c:1191
#11 0x00000000004e7467 in ngx_http_lua_content_wev_handler (r=0x2224b60)
    at ../ngx_lua-0.5.0rc30/src/ngx_http_lua_contentby.c:100
#12 0x0000000000464d9a in ngx_http_run_posted_requests (c=0x7f8a973db190) at src/http/ngx_http_request.c:1859
#13 0x000000000047a1e0 in ngx_http_upstream_handler (ev=0x7f8a973721b0) at src/http/ngx_http_upstream.c:921
#14 0x000000000043fc89 in ngx_event_process_posted (cycle=0x22177a0, posted=0x7861f8) at src/event/ngx_event_posted.c:40
#15 0x000000000043db8c in ngx_process_events_and_timers (cycle=0x22177a0) at src/event/ngx_event.c:273
#16 0x000000000044a651 in ngx_worker_process_cycle (cycle=0x22177a0, data=0x0) at src/os/unix/ngx_process_cycle.c:802
#17 0x000000000044713a in ngx_spawn_process (cycle=0x22177a0, proc=0x44a495 <ngx_worker_process_cycle>, data=0x0,
    name=0x539b4b "worker process", respawn=1) at src/os/unix/ngx_process.c:197
#18 0x000000000044a0cc in ngx_reap_children (cycle=0x22177a0) at src/os/unix/ngx_process_cycle.c:618
#19 0x0000000000448dcd in ngx_master_process_cycle (cycle=0x22177a0) at src/os/unix/ngx_process_cycle.c:181
#20 0x000000000041a5e6 in main (argc=1, argv=0x7ffff3617068) at src/core/nginx.c:412

using openresty, compiled so:

./configure --prefix=/home/sztanpet/openresty --without-http_xss_module --with-ipv6 --with-http_sub_module --with-http_gzip_static_module --without-http_charset_module --without-http_geo_module --without-http_empty_gif_module --without-mail_pop3_module --without-mail_imap_module --without-mail_smtp_module --with-pcre --with-http_postgres_module --with-debug

full code that sometimes triggers it including comments and anything, maybe its lua bytecode related somehow:

local args       = ngx.req.get_uri_args()
local questionid = tonumber( args.questionid )
local answerid   = tonumber( args.answerid )
ngx.header.content_type = "application/json; charset=UTF-8"

if not questionid or not answerid or questionid == 0 or answerid == 0 then
  ngx.say('{"success":false, "err":"invalidparams"}')
  return ngx.exit(ngx.HTTP_OK)
end

local ipaddress   = ngx.var.remote_addr
local parser      = require "redis.parser"
local questionkey = 'question_' .. questionid
local ipsetkey    = "ipset_question_" .. questionid

local requests    = {
  parser.build_query({'hexists', questionkey, answerid}),
  parser.build_query({'sadd', ipsetkey, ipaddress}),
}
local params      = {body = table.concat(requests)}
local result      = ngx.location.capture("/redis?2", params)

if result.status ~= 200 or not result.body then
  ngx.log(ngx.ERR, "failed to query redis")
  ngx.exit(500)
end

local replies = parser.parse_replies(result.body, #requests)

if replies[1][1] ~= 1 then -- avoid setting cookie if the answer is non-existant
  ngx.say('{"success":false, "err":"invalidparams"}')
  return ngx.exit(ngx.HTTP_OK)
end

local cookie      = {
  'vote-',
  questionid,
  '=',
  answerid,
  '; expires=',
  ngx.cookie_time( ngx.time() + 3240000 ),
  '; path=/;'
}
ngx.header['Set-Cookie'] = table.concat(cookie)
--[[
if replies[2][1] == 1 then
  ngx.say('{"success":false, "err":"alreadyvoted"}')
  return ngx.exit(ngx.HTTP_OK)
end
]]
-- reuse table, there is a very small chance that the sadd will fail (race with other requests)
requests[1] = parser.build_query({'sadd', ipsetkey, ipaddress})
requests[2] = parser.build_query({'hincrby', questionkey, answerid, 1})
requests[3] = parser.build_query({'hgetall', questionkey})

params.body  = table.concat(requests)
local result = ngx.location.capture("/redis?3", params)

if result.status ~= 200 or not result.body then
  ngx.log(ngx.ERR, "failed to query redis")
  ngx.exit(500)
end

local replies = parser.parse_replies(result.body, #requests)

if replies[1][1] ~= 1 then -- failed to add ip, meaning the race really happened, handle it
  requests[1] = parser.build_query({'hincrby', questionkey, answerid, -1})
  requests[2] = parser.build_query({'hgetall', questionkey})
  requests[3] = nil

  params.body = table.concat(requests)
  result      = ngx.location.capture("/redis?2", params)

  if result.status ~= 200 or not result.body then
    ngx.log(ngx.ERR, "failed to query redis")
    ngx.exit(500)
  end

  replies = parser.parse_replies(result.body, #requests)
  table.insert(replies, 1, "") -- shift elements down

end

local ret   = {success = true, data = {}}
local reply = replies[3]

for i = 1, #reply, 2 do
  ngx.print(reply[i], reply[i+1])
  ret.data[ reply[i] ] = reply[i+1]
end

--local json = require "cjson"
--ngx.say(json.encode(ret))

-- try and sync the votes to postgres
local postgresupdating = true --ngx.shared.DICT.get('postgresupdating')
if postgresupdating then
  return ngx.exit(ngx.HTTP_OK)
end

ngx.flush()
ngx.exit(ngx.HTTP_OK)
--ngx.shared.DICT.set('postgresupdating', true)

local sql = {}
for k, v in pairs(ret.data) do
  table.insert(sql, "UPDATE answers SET count = '" .. v .. "' WHERE answerid = '" .. k .. "';")
end
local reply = ngx.location.capture("/postgres", {
  method = ngx.HTTP_POST,
  body = table.concat(sql)
})

--ngx.shared.DICT.set('postgresupdating', false)

relevant nginx config

    location /redis {
      internal;
      redis2_raw_queries $args $echo_request_body;
      redis2_pass redis;
    }
upstream redis {
    server 127.0.0.1:6379;
    keepalive 1024 single;
}

sztanpet · 2012-06-23T20:07:44Z

also, lua_code_cache is off,
distro is gentoo with redhat kernel,
gcc-4.4.5

Linux feanor 2.6.35-28.50 #1 SMP Mon Oct 17 23:44:59 CEST 2011 x86_64 Intel(R) Pentium(R) Dual CPU E2160 @ 1.80GHz GenuineIntel GNU/Linux

sztanpet · 2012-06-23T20:20:26Z

https://dl.dropbox.com/u/195588/core.442 and the core dump

agentzh · 2012-06-24T03:05:47Z

Hello!

On Sun, Jun 24, 2012 at 3:57 AM, sztanpet
reply@reply.github.com
wrote:

seems I have a similar issue,
here is a backtrace for starters

Thank you for the bug report! Just want to ask a few questions:

Is there anything interesting in your error.log?
Do you have to run multiple concurrent requests (i.e., concurrency
level > 1) to reproduce this issue?
Can you reproduce this with lua_code_cache on?
Can you reproduce this with LuaJIT 2.0 instead of the standard Lua
5.1.4 interpreter?
Could you please run valgrind's memcheck tool upon your nginx to
see if there's any memory issues prior to the crash? Basically, you
need to turn off both "daemon" and "master_process" in your nginx.conf
and run your nginx like this:

valgrind --leak-check=full /path/to/your/nginx ...

You're recommended to rebuild your openresty using the
--with-no-pool-patch configure option before running it with valgrind,
so as to prevent nginx's memory pool from interfering with tools like
valgrind.

Could you please try minimizing the sample code on your side to the
point that I can easily run and debug the bad example directly on my
side?

Best regards,
-agentzh

sztanpet · 2012-06-24T05:08:15Z

no, there is nothing in my error.log, (error_log /dev/kmsg error;)
no, i did not have to run multiple concurrent requests, I just edit the code and reload the page and sometimes there is a segfault

minimizing the sample code didnt seem like a good idea because the crashes were random, the only thing I noticed was that after the subrequest I'm trying to construct a lua hash from a redis hash and it didn't work (upon trying to print all the values I get an empty string for the value, but in the request.body I see that a value should be there) and json.encode errors out with saying that it cannot encode illegal values.

the redis data was hset question_1 1 5

sztanpet · 2012-06-24T05:34:14Z

with lua_code_cache on, daemon off, master_process off
also with lua 5.1.4

[07:27](/home/sztanpet/openresty/nginx/sbin)# valgrind  --leak-check=full ./nginx
==23244== Memcheck, a memory error detector
==23244== Copyright (C) 2002-2010, and GNU GPL'd, by Julian Seward et al.
==23244== Using Valgrind-3.6.1 and LibVEX; rerun with -h for copyright info
==23244== Command: ./nginx
==23244==
==23244== Invalid read of size 4
==23244==    at 0x524F8E: luaH_next (in /home/sztanpet/openresty/nginx/sbin/nginx)
==23244==    by 0x51B16B: lua_next (in /home/sztanpet/openresty/nginx/sbin/nginx)
==23244==    by 0x4D6447: ngx_http_lua_calc_strlen_in_table (ngx_http_lua_output.c:253)
==23244==    by 0x4D5EC6: ngx_http_lua_ngx_echo (ngx_http_lua_output.c:108)
==23244==    by 0x4D5CF6: ngx_http_lua_ngx_print (ngx_http_lua_output.c:24)
==23244==    by 0x51E078: luaD_precall (in /home/sztanpet/openresty/nginx/sbin/nginx)
==23244==    by 0x5276C8: luaV_execute (in /home/sztanpet/openresty/nginx/sbin/nginx)
==23244==    by 0x51DC16: luaD_rawrunprotected (in /home/sztanpet/openresty/nginx/sbin/nginx)
==23244==    by 0x51DDDF: lua_resume (in /home/sztanpet/openresty/nginx/sbin/nginx)
==23244==    by 0x4E305D: ngx_http_lua_run_thread (ngx_http_lua_util.c:775)
==23244==    by 0x4E3DA1: ngx_http_lua_wev_handler (ngx_http_lua_util.c:1191)
==23244==    by 0x4E70BE: ngx_http_lua_content_wev_handler (ngx_http_lua_contentby.c:100)
==23244==  Address 0x4014000000000038 is not stack'd, malloc'd or (recently) free'd
==23244==
==23244==
==23244== Process terminating with default action of signal 11 (SIGSEGV)
==23244==  General Protection Fault
==23244==    at 0x524F8E: luaH_next (in /home/sztanpet/openresty/nginx/sbin/nginx)
==23244==    by 0x51B16B: lua_next (in /home/sztanpet/openresty/nginx/sbin/nginx)
==23244==    by 0x4D6447: ngx_http_lua_calc_strlen_in_table (ngx_http_lua_output.c:253)
==23244==    by 0x4D5EC6: ngx_http_lua_ngx_echo (ngx_http_lua_output.c:108)
==23244==    by 0x4D5CF6: ngx_http_lua_ngx_print (ngx_http_lua_output.c:24)
==23244==    by 0x51E078: luaD_precall (in /home/sztanpet/openresty/nginx/sbin/nginx)
==23244==    by 0x5276C8: luaV_execute (in /home/sztanpet/openresty/nginx/sbin/nginx)
==23244==    by 0x51DC16: luaD_rawrunprotected (in /home/sztanpet/openresty/nginx/sbin/nginx)
==23244==    by 0x51DDDF: lua_resume (in /home/sztanpet/openresty/nginx/sbin/nginx)
==23244==    by 0x4E305D: ngx_http_lua_run_thread (ngx_http_lua_util.c:775)
==23244==    by 0x4E3DA1: ngx_http_lua_wev_handler (ngx_http_lua_util.c:1191)
==23244==    by 0x4E70BE: ngx_http_lua_content_wev_handler (ngx_http_lua_contentby.c:100)
==23244==
==23244== HEAP SUMMARY:
==23244==     in use at exit: 2,380,423 bytes in 6,945 blocks
==23244==   total heap usage: 8,111 allocs, 1,166 frees, 2,553,637 bytes allocated
==23244==
==23244== 292 (52 direct, 240 indirect) bytes in 1 blocks are definitely lost in loss record 1,890 of 2,140
==23244==    at 0x4C267CE: malloc (vg_replace_malloc.c:236)
==23244==    by 0x64834CB: nss_parse_service_list (nsswitch.c:540)
==23244==    by 0x6483CA5: __nss_database_lookup (nsswitch.c:134)
==23244==    by 0x6AFD32F: ???
==23244==    by 0x6AFE384: ???
==23244==    by 0x644255C: getpwnam_r@@GLIBC_2.2.5 (getXXbyYY_r.c:253)
==23244==    by 0x6441F3F: getpwnam (getXXbyYY.c:117)
==23244==    by 0x41BD9D: ngx_set_user (nginx.c:1147)
==23244==    by 0x433C23: ngx_conf_handler (ngx_conf_file.c:394)
==23244==    by 0x4337B7: ngx_conf_parse (ngx_conf_file.c:244)
==23244==    by 0x430366: ngx_init_cycle (ngx_cycle.c:268)
==23244==    by 0x41A36F: main (nginx.c:333)
==23244==
==23244== 292 (52 direct, 240 indirect) bytes in 1 blocks are definitely lost in loss record 1,891 of 2,140
==23244==    at 0x4C267CE: malloc (vg_replace_malloc.c:236)
==23244==    by 0x64834CB: nss_parse_service_list (nsswitch.c:540)
==23244==    by 0x6483CA5: __nss_database_lookup (nsswitch.c:134)
==23244==    by 0x6AFC40F: ???
==23244==    by 0x6AFCEDC: ???
==23244==    by 0x64412AC: getgrnam_r@@GLIBC_2.2.5 (getXXbyYY_r.c:253)
==23244==    by 0x644085F: getgrnam (getXXbyYY.c:117)
==23244==    by 0x41BE3A: ngx_set_user (nginx.c:1159)
==23244==    by 0x433C23: ngx_conf_handler (ngx_conf_file.c:394)
==23244==    by 0x4337B7: ngx_conf_parse (ngx_conf_file.c:244)
==23244==    by 0x430366: ngx_init_cycle (ngx_cycle.c:268)
==23244==    by 0x41A36F: main (nginx.c:333)
==23244==
==23244== LEAK SUMMARY:
==23244==    definitely lost: 104 bytes in 2 blocks
==23244==    indirectly lost: 480 bytes in 20 blocks
==23244==      possibly lost: 0 bytes in 0 blocks
==23244==    still reachable: 2,379,839 bytes in 6,923 blocks
==23244==         suppressed: 0 bytes in 0 blocks
==23244== Reachable blocks (those to which a pointer was found) are not shown.
==23244== To see them, rerun with: --leak-check=full --show-reachable=yes
==23244==
==23244== For counts of detected and suppressed errors, rerun with: -v
==23244== ERROR SUMMARY: 3 errors from 3 contexts (suppressed: 7 from 7)
Segmentation fault

agentzh · 2012-06-24T05:36:43Z

Thank you for the valgrind output!

Could you also use "error_log /dev/kmsg debug;" and paste out all the debug logs in your error.log right before the crash?

sztanpet · 2012-06-24T05:38:26Z

[07:37](/home/sztanpet/openresty/nginx/sbin)# dmesg -c
[7508426.898105] 2012/06/24 07:37:30 [debug] 23293#0: epoll add event: fd:6 op:1 ev:00000001
[7508427.015612] 2012/06/24 07:37:30 [debug] 23293#0: accept on 0.0.0.0:81, ready: 0
[7508427.021222] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D0270:56
[7508427.021918] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D02F0:16
[7508427.021964] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D0340:16
[7508427.022855] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D0390:48
[7508427.022901] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D0400:16
[7508427.026293] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D0450:15
[7508427.026340] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D04A0:16
[7508427.028269] 2012/06/24 07:37:30 [debug] 23293#0: *1 accept: 192.168.1.2 fd:7
[7508427.029309] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D04F0:24
[7508427.029360] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D0550:16
[7508427.035755] 2012/06/24 07:37:30 [debug] 23293#0: *1 event timer add: 7: 60000:1340516310527
[7508427.038170] 2012/06/24 07:37:30 [debug] 23293#0: *1 epoll add event: fd:7 op:1 ev:80000001
[7508427.041644] 2012/06/24 07:37:30 [debug] 23293#0: accept on 0.0.0.0:81, ready: 0
[7508427.041735] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D05A0:56
[7508427.041780] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D0620:16
[7508427.041821] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D0670:16
[7508427.041867] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D06C0:48
[7508427.041907] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D0730:16
[7508427.041952] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D0780:15
[7508427.041992] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D07D0:16
[7508427.042044] 2012/06/24 07:37:30 [debug] 23293#0: *2 accept: 192.168.1.2 fd:8
[7508427.042086] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D0820:24
[7508427.042126] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069D0880:16
[7508427.042172] 2012/06/24 07:37:30 [debug] 23293#0: *2 event timer add: 8: 60000:1340516310527
[7508427.044193] 2012/06/24 07:37:30 [debug] 23293#0: *2 epoll add event: fd:8 op:1 ev:80000001
[7508427.045360] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D08D0:48
[7508427.045410] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D0940:16
[7508427.046160] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D0990:1264
[7508427.046210] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D0EC0:16
[7508427.049749] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D0F10:80
[7508427.049800] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D0FA0:16
[7508427.050439] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D0FF0:1024
[7508427.050488] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D1430:16
[7508427.052349] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D1480:56
[7508427.053137] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D1500:960
[7508427.053187] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D1900:16
[7508427.054527] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D1950:432
[7508427.054577] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D1B40:16
[7508427.055264] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D1B90:384
[7508427.055313] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D1D50:16
[7508427.058406] 2012/06/24 07:37:30 [debug] 23293#0: *1 http process request line
[7508427.062008] 2012/06/24 07:37:30 [debug] 23293#0: *1 recv: fd:7 502 of 1024
[7508427.079218] 2012/06/24 07:37:30 [debug] 23293#0: *1 http request line: "GET /vote?questionid=1&answerid=1 HTTP/1.1"
[7508427.079667] 2012/06/24 07:37:30 [debug] 23293#0: *1 http uri: "/vote"
[7508427.080149] 2012/06/24 07:37:30 [debug] 23293#0: *1 http args: "questionid=1&answerid=1"
[7508427.080597] 2012/06/24 07:37:30 [debug] 23293#0: *1 http exten: ""
[7508427.081474] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D1DA0:960
[7508427.081529] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D21A0:16
[7508427.082483] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D21F0:16
[7508427.082532] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2240:16
[7508427.084171] 2012/06/24 07:37:30 [debug] 23293#0: *1 http process request header line
[7508427.094501] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2290:4
[7508427.094552] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D22E0:16
[7508427.100951] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2330:17
[7508427.101001] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2390:16
[7508427.103019] 2012/06/24 07:37:30 [debug] 23293#0: *1 http header: "Host: sztanpet.local:81"
[7508427.103206] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D23E0:10
[7508427.103253] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2430:16
[7508427.106726] 2012/06/24 07:37:30 [debug] 23293#0: *1 http header: "Connection: keep-alive"
[7508427.106797] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2480:13
[7508427.106843] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D24D0:16
[7508427.107453] 2012/06/24 07:37:30 [debug] 23293#0: *1 http header: "Cache-Control: max-age=0"
[7508427.108480] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2520:10
[7508427.108528] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2570:16
[7508427.113747] 2012/06/24 07:37:30 [debug] 23293#0: *1 http header: "User-Agent: Mozilla/5.0 (Windows NT 6.0; WOW64) AppleWebKit/536.11 (KHTML, like Gecko) Chrome/20.0.1132.42 Safari/536.11"
[7508427.113828] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D25C0:6
[7508427.113873] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2610:16
[7508427.114169] 2012/06/24 07:37:30 [debug] 23293#0: *1 http header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
[7508427.114236] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2660:15
[7508427.114281] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D26B0:16
[7508427.114898] 2012/06/24 07:37:30 [debug] 23293#0: *1 http header: "Accept-Encoding: gzip,deflate,sdch"
[7508427.114969] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2700:15
[7508427.115015] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2750:16
[7508427.115057] 2012/06/24 07:37:30 [debug] 23293#0: *1 http header: "Accept-Language: en,en-GB;q=0.8,en-US;q=0.6,hu;q=0.4"
[7508427.115114] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D27A0:14
[7508427.115158] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D27F0:16
[7508427.115403] 2012/06/24 07:37:30 [debug] 23293#0: *1 http header: "Accept-Charset: UTF-8,*;q=0.5"
[7508427.115472] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2840:6
[7508427.115517] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2890:16
[7508427.116463] 2012/06/24 07:37:30 [debug] 23293#0: *1 http header: "Cookie: PHPSESSID=765bd360856d75587bb50be68e0f6126; vote-1=1"
[7508427.118063] 2012/06/24 07:37:30 [debug] 23293#0: *1 http header done
[7508427.122529] 2012/06/24 07:37:30 [debug] 23293#0: *1 event timer del: 7: 1340516310527
[7508427.129206] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 0
[7508427.131056] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 1
[7508427.135416] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: "/"
[7508427.137700] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: "redis"
[7508427.138040] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: "vote"
[7508427.141255] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: ~ "\.php$"
[7508427.155527] 2012/06/24 07:37:30 [debug] 23293#0: *1 using configuration "/vote"
[7508427.161405] 2012/06/24 07:37:30 [debug] 23293#0: *1 http cl:-1 max:1048576
[7508427.162026] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 3
[7508427.162068] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 4
[7508427.162721] 2012/06/24 07:37:30 [debug] 23293#0: *1 post rewrite phase: 5
[7508427.163831] 2012/06/24 07:37:30 [debug] 23293#0: *1 generic phase: 6
[7508427.165430] 2012/06/24 07:37:30 [debug] 23293#0: *1 generic phase: 7
[7508427.167087] 2012/06/24 07:37:30 [debug] 23293#0: *1 access phase: 8
[7508427.168370] 2012/06/24 07:37:30 [debug] 23293#0: *1 access phase: 9
[7508427.169316] 2012/06/24 07:37:30 [debug] 23293#0: *1 access phase: 10
[7508427.170640] 2012/06/24 07:37:30 [debug] 23293#0: *1 post access phase: 11
[7508427.172230] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua content handler, uri "/vote"
[7508427.173238] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D28E0:280
[7508427.173289] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2A40:16
[7508427.176755] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2A90:35
[7508427.176804] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069D2B00:16
[7508427.375530] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua reset ctx
[7508427.378328] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua creating new thread
[7508427.394657] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069DD6B0:24
[7508427.394708] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069DD710:16
[7508427.395709] 2012/06/24 07:37:30 [debug] 23293#0: *1 http cleanup add: 00000000069DD6B0
[7508427.397396] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run thread
[7508427.408263] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069DD8C0:23
[7508427.408315] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069DD920:16
[7508427.421105] 2012/06/24 07:37:30 [debug] 23293#0: *1 free: 00000000069DD8C0
[7508427.436085] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069DE080:13
[7508427.436138] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069DE0D0:16
[7508427.439666] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069DE120:31
[7508427.439716] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069DE180:16
[7508427.453245] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069DE1D0:11
[7508427.453297] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069DE220:16
[7508427.588060] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E3D70:32
[7508427.588115] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E3DD0:16
[7508427.598562] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E3FC0:48
[7508427.598612] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4030:16
[7508427.599651] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4080:80
[7508427.599700] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4110:16
[7508427.599750] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4160:96
[7508427.599795] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4200:16
[7508427.601123] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4250:16
[7508427.601172] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E42A0:16
[7508427.603551] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E42F0:8
[7508427.603600] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4340:16
[7508427.607860] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4390:16
[7508427.607910] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E43E0:16
[7508427.608489] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4430:280
[7508427.608537] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4590:16
[7508427.610444] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E45E0:1264
[7508427.610494] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4B10:16
[7508427.611101] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4B60:432
[7508427.611151] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4D50:16
[7508427.611967] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E4DA0:960
[7508427.612016] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E51A0:16
[7508427.615970] 2012/06/24 07:37:30 [debug] 23293#0: *1 http subrequest "/redis?2"
[7508427.619518] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E51F0:24
[7508427.619570] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E5250:16
[7508427.622663] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E52A0:16
[7508427.622715] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E52F0:16
[7508427.626267] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E5340:960
[7508427.626317] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E5740:16
[7508427.628105] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E5790:14
[7508427.628154] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E57E0:16
[7508427.629338] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E5830:20
[7508427.629387] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E5890:16
[7508427.634963] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E58E0:384
[7508427.635013] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E5AA0:16
[7508427.639161] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua resume returned 1
[7508427.640203] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua thread yielded
[7508427.644048] 2012/06/24 07:37:30 [debug] 23293#0: *1 http finalize request: -4, "/vote?questionid=1&answerid=1" a:0, c:3
[7508427.645866] 2012/06/24 07:37:30 [debug] 23293#0: *1 http request count:3 blk:0
[7508427.648856] 2012/06/24 07:37:30 [debug] 23293#0: *1 http posted request: "/redis?2"
[7508427.650131] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 0
[7508427.650174] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 1
[7508427.650217] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: "/"
[7508427.650256] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: "redis"
[7508427.650298] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: ~ "\.php$"
[7508427.650358] 2012/06/24 07:37:30 [debug] 23293#0: *1 using configuration "/redis"
[7508427.650579] 2012/06/24 07:37:30 [debug] 23293#0: *1 http cl:96 max:1048576
[7508427.651140] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 3
[7508427.651180] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 4
[7508427.651219] 2012/06/24 07:37:30 [debug] 23293#0: *1 post rewrite phase: 5
[7508427.651264] 2012/06/24 07:37:30 [debug] 23293#0: *1 generic phase: 6
[7508427.651306] 2012/06/24 07:37:30 [debug] 23293#0: *1 generic phase: 7
[7508427.653611] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E5AF0:832
[7508427.653664] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E5E70:16
[7508427.655562] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E5EC0:64
[7508427.655612] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E5F40:16
[7508427.657313] 2012/06/24 07:37:30 [debug] 23293#0: *1 http init upstream, client timer: 0
[7508427.659103] 2012/06/24 07:37:30 [debug] 23293#0: *1 epoll add event: fd:7 op:3 ev:80000005
[7508427.667717] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E5F90:96
[7508427.667767] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6030:16
[7508427.672025] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6080:96
[7508427.672075] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6120:16
[7508427.676084] 2012/06/24 07:37:30 [debug] 23293#0: *1 http script var: "*3
[7508427.676087] $7
[7508427.676088] hexists
[7508427.676089] $10
[7508427.676090] question_1
[7508427.676090] $1
[7508427.676091] 1
[7508427.676092] *3
[7508427.676093] $4
[7508427.676094] sadd
[7508427.676095] $16
[7508427.676096] ipset_question_1
[7508427.676097] $11
[7508427.676097] 192.168.1.2
[7508427.676098] "
[7508427.678707] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6170:1
[7508427.678760] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E61C0:16
[7508427.678805] 2012/06/24 07:37:30 [debug] 23293#0: *1 http script var: "2"
[7508427.680087] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6210:80
[7508427.680138] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E62A0:16
[7508427.680189] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E62F0:96
[7508427.680234] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6390:16
[7508427.681171] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E63E0:16
[7508427.681220] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6430:16
[7508427.682093] 2012/06/24 07:37:30 [debug] 23293#0: *1 http redis2 request: ""
[7508427.683874] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6480:40
[7508427.683924] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E64F0:16
[7508427.683984] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6540:56
[7508427.684029] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E65C0:16
[7508427.684747] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6610:24
[7508427.684796] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6670:16
[7508427.684836] 2012/06/24 07:37:30 [debug] 23293#0: *1 http cleanup add: 00000000069E6610
[7508427.686488] 2012/06/24 07:37:30 [debug] 23293#0: *1 init keepalive peer
[7508427.686902] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E66C0:64
[7508427.686950] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6740:16
[7508427.688056] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6790:32
[7508427.688104] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E67F0:16
[7508427.694497] 2012/06/24 07:37:30 [debug] 23293#0: *1 get keepalive peer
[7508427.695829] 2012/06/24 07:37:30 [debug] 23293#0: *1 get rr peer, try: 1
[7508427.698892] 2012/06/24 07:37:30 [debug] 23293#0: *1 socket 9
[7508427.703747] 2012/06/24 07:37:30 [debug] 23293#0: *1 epoll add connection: fd:9 ev:80000005
[7508427.705274] 2012/06/24 07:37:30 [debug] 23293#0: *1 connect to 127.0.0.1:6379, fd:9 #3
[7508427.708320] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream connect: -2
[7508427.713296] 2012/06/24 07:37:30 [debug] 23293#0: *1 event timer add: 9: 60000:1340516310527
[7508427.714893] 2012/06/24 07:37:30 [debug] 23293#0: *1 http finalize request: -4, "/redis?2" a:1, c:3
[7508427.714937] 2012/06/24 07:37:30 [debug] 23293#0: *1 http request count:3 blk:0
[7508427.716139] 2012/06/24 07:37:30 [debug] 23293#0: accept on 0.0.0.0:81, ready: 0
[7508427.716243] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069E6840:56
[7508427.716290] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069E68C0:16
[7508427.716331] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069E6910:16
[7508427.716377] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069E6960:48
[7508427.716416] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069E69D0:16
[7508427.716463] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069E6A20:15
[7508427.716502] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069E6A70:16
[7508427.716556] 2012/06/24 07:37:30 [debug] 23293#0: *4 accept: 192.168.1.2 fd:10
[7508427.716599] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069E6AC0:24
[7508427.716639] 2012/06/24 07:37:30 [debug] 23293#0: malloc: 00000000069E6B20:16
[7508427.716686] 2012/06/24 07:37:30 [debug] 23293#0: *4 event timer add: 10: 60000:1340516310527
[7508427.719373] 2012/06/24 07:37:30 [debug] 23293#0: *4 epoll add event: fd:10 op:1 ev:80000001
[7508427.721535] 2012/06/24 07:37:30 [debug] 23293#0: *1 http run request: "/redis?2"
[7508427.722972] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream check client, write event:1, "/redis"
[7508427.727861] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream recv(): -1 (11: Resource temporarily unavailable)
[7508427.730451] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream request: "/redis?2"
[7508427.731845] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream send request handler
[7508427.733498] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream send request
[7508427.740650] 2012/06/24 07:37:30 [debug] 23293#0: *1 chain writer buf fl:0 s:96
[7508427.741118] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6B70:16
[7508427.741167] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6BC0:16
[7508427.742260] 2012/06/24 07:37:30 [debug] 23293#0: *1 chain writer in: 00000000069E6B70
[7508427.751094] 2012/06/24 07:37:30 [debug] 23293#0: *1 writev: 96
[7508427.754873] 2012/06/24 07:37:30 [debug] 23293#0: *1 chain writer out: 0000000000000000
[7508427.757041] 2012/06/24 07:37:30 [debug] 23293#0: *1 event timer del: 9: 1340516310527
[7508427.762493] 2012/06/24 07:37:30 [debug] 23293#0: *1 event timer add: 9: 60000:1340516310527
[7508427.764553] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream request: "/redis?2"
[7508427.765721] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream process header
[7508427.766913] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E6C10:4096
[7508427.766964] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E7C50:16
[7508427.768463] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E7CA0:384
[7508427.768513] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E7E60:16
[7508427.769946] 2012/06/24 07:37:30 [debug] 23293#0: *1 recv: fd:9 8 of 4096
[7508427.777775] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture header filter, uri "/redis"
[7508427.779279] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capturing response body
[7508427.783271] 2012/06/24 07:37:30 [debug] 23293#0: *1 tcp_nodelay
[7508427.789139] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E7EB0:16
[7508427.789191] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E7F00:16
[7508427.789749] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E7F50:80
[7508427.789805] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E7FE0:16
[7508427.794222] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream process non buffered downstream
[7508427.796220] 2012/06/24 07:37:30 [debug] 23293#0: *1 http output filter "/redis?2"
[7508427.797800] 2012/06/24 07:37:30 [debug] 23293#0: *1 http copy filter: "/redis?2"
[7508427.798524] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E8030:104
[7508427.798573] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E80E0:16
[7508427.805003] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture body filter, uri "/redis"
[7508427.806649] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture body filter capturing response body, uri "/redis"
[7508427.809651] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E8130:16
[7508427.809701] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E8180:16
[7508427.810287] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua allocate new chainlink and new buf of size 8, cl:00000000069E8130
[7508427.810713] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E81D0:80
[7508427.810761] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E8260:16
[7508427.810811] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E82B0:8
[7508427.810855] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E8300:16
[7508427.816486] 2012/06/24 07:37:30 [debug] 23293#0: *1 http copy filter: 0 "/redis?2"
[7508427.821209] 2012/06/24 07:37:30 [debug] 23293#0: *1 finalize http upstream request: 0
[7508427.823632] 2012/06/24 07:37:30 [debug] 23293#0: *1 finalize http redis2 request
[7508427.825104] 2012/06/24 07:37:30 [debug] 23293#0: *1 free keepalive peer
[7508427.828573] 2012/06/24 07:37:30 [debug] 23293#0: *1 free keepalive peer: saving connection 00000000068403F0
[7508427.830988] 2012/06/24 07:37:30 [debug] 23293#0: *1 event timer del: 9: 1340516310527
[7508427.836918] 2012/06/24 07:37:30 [debug] 23293#0: *1 free rr peer 1 0
[7508427.839792] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E8350:80
[7508427.839842] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E83E0:16
[7508427.841321] 2012/06/24 07:37:30 [debug] 23293#0: *1 http output filter "/redis?2"
[7508427.841364] 2012/06/24 07:37:30 [debug] 23293#0: *1 http copy filter: "/redis?2"
[7508427.842381] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture body filter, uri "/redis"
[7508427.842425] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture body filter capturing response body, uri "/redis"
[7508427.843504] 2012/06/24 07:37:30 [debug] 23293#0: *1 http copy filter: 0 "/redis?2"
[7508427.844275] 2012/06/24 07:37:30 [debug] 23293#0: *1 http finalize request: 0, "/redis?2" a:1, c:2
[7508427.846437] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run post subrequest handler: rc:0, waiting:0, done:0
[7508427.848877] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua restoring write event handler
[7508427.851270] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E8430:8
[7508427.851319] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E8480:16
[7508427.857194] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E84D0:16
[7508427.857244] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E8520:16
[7508427.857804] 2012/06/24 07:37:30 [debug] 23293#0: *1 http wake parent request: "/vote?questionid=1&answerid=1"
[7508427.859429] 2012/06/24 07:37:30 [debug] 23293#0: *1 http posted request: "/vote?questionid=1&answerid=1"
[7508427.860608] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run write event handler
[7508427.864349] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run subrequests done, resuming lua thread
[7508427.865415] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua handle subrequest responses
[7508427.868359] 2012/06/24 07:37:30 [debug] 23293#0: *1 free: 00000000069E8430
[7508427.872748] 2012/06/24 07:37:30 [debug] 23293#0: *1 free: 00000000069E3D70
[7508427.873481] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run thread
[7508427.890858] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9070:11
[7508427.890910] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E90C0:16
[7508427.891238] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9110:54
[7508427.891285] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9190:16
[7508427.893592] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E91E0:10
[7508427.893641] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9230:16
[7508427.896445] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9B50:32
[7508427.896495] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9BB0:16
[7508427.896602] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9C00:48
[7508427.896647] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9C70:16
[7508427.896697] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9CC0:80
[7508427.896741] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9D50:16
[7508427.896788] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9DA0:137
[7508427.896832] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9E70:16
[7508427.896880] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9EC0:16
[7508427.896923] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9F10:16
[7508427.896975] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9F60:8
[7508427.897020] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069E9FB0:16
[7508427.897087] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EA000:16
[7508427.897132] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EA050:16
[7508427.897178] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EA0A0:280
[7508427.897221] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EA200:16
[7508427.897273] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EA250:1264
[7508427.897316] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EA780:16
[7508427.897369] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EA7D0:432
[7508427.897412] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EA9C0:16
[7508427.897461] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EAA10:960
[7508427.897505] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EAE10:16
[7508427.897547] 2012/06/24 07:37:30 [debug] 23293#0: *1 http subrequest "/redis?3"
[7508427.897598] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EAE60:24
[7508427.897641] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EAEC0:16
[7508427.897688] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EAF10:16
[7508427.897731] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EAF60:16
[7508427.897787] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EAFB0:960
[7508427.897831] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EB3B0:16
[7508427.897879] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EB400:14
[7508427.897922] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EB450:16
[7508427.897972] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EB4A0:20
[7508427.898015] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EB500:16
[7508427.898083] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EB550:384
[7508427.898127] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EB710:16
[7508427.898177] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua resume returned 1
[7508427.898210] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua thread yielded
[7508427.899022] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run thread returned -2
[7508427.899533] 2012/06/24 07:37:30 [debug] 23293#0: *1 http posted request: "/redis?3"
[7508427.899576] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 0
[7508427.899615] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 1
[7508427.899656] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: "/"
[7508427.899695] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: "redis"
[7508427.899737] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: ~ "\.php$"
[7508427.899794] 2012/06/24 07:37:30 [debug] 23293#0: *1 using configuration "/redis"
[7508427.899837] 2012/06/24 07:37:30 [debug] 23293#0: *1 http cl:137 max:1048576
[7508427.899873] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 3
[7508427.899910] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 4
[7508427.899947] 2012/06/24 07:37:30 [debug] 23293#0: *1 post rewrite phase: 5
[7508427.899982] 2012/06/24 07:37:30 [debug] 23293#0: *1 generic phase: 6
[7508427.900062] 2012/06/24 07:37:30 [debug] 23293#0: *1 generic phase: 7
[7508427.900130] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EB760:832
[7508427.900177] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EBAE0:16
[7508427.900233] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EBB30:64
[7508427.900277] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EBBB0:16
[7508427.900317] 2012/06/24 07:37:30 [debug] 23293#0: *1 http init upstream, client timer: 0
[7508427.900384] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EBC00:137
[7508427.900427] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EBCD0:16
[7508427.900480] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EBD20:137
[7508427.900524] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EBDF0:16
[7508427.900574] 2012/06/24 07:37:30 [debug] 23293#0: *1 http script var: "*3
[7508427.900576] $4
[7508427.900577] sadd
[7508427.900578] $16
[7508427.900579] ipset_question_1
[7508427.900580] $11
[7508427.900581] 192.168.1.2
[7508427.900581] *4
[7508427.900582] $7
[7508427.900583] hincrby
[7508427.900584] $10
[7508427.900585] question_1
[7508427.900586] $1
[7508427.900587] 1
[7508427.900587] $1
[7508427.900588] 1
[7508427.900589] *2
[7508427.900590] $7
[7508427.900591] hgetall
[7508427.900592] $10
[7508427.900593] question_1
[7508427.900594] "
[7508427.900651] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EBE40:1
[7508427.900694] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EBE90:16
[7508427.900733] 2012/06/24 07:37:30 [debug] 23293#0: *1 http script var: "3"
[7508427.900784] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EBEE0:80
[7508427.900827] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EBF70:16
[7508427.900884] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EBFC0:137
[7508427.900928] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC090:16
[7508427.900976] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC0E0:16
[7508427.901019] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC130:16
[7508427.901056] 2012/06/24 07:37:30 [debug] 23293#0: *1 http redis2 request: ""
[7508427.901102] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC180:40
[7508427.901145] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC1F0:16
[7508427.901190] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC240:56
[7508427.901232] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC2C0:16
[7508427.901278] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC310:24
[7508427.901322] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC370:16
[7508427.901360] 2012/06/24 07:37:30 [debug] 23293#0: *1 http cleanup add: 00000000069EC310
[7508427.901395] 2012/06/24 07:37:30 [debug] 23293#0: *1 init keepalive peer
[7508427.901439] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC3C0:64
[7508427.901482] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC440:16
[7508427.901529] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC490:32
[7508427.901572] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC4F0:16
[7508427.901616] 2012/06/24 07:37:30 [debug] 23293#0: *1 get keepalive peer
[7508427.903479] 2012/06/24 07:37:30 [debug] 23293#0: *1 get keepalive peer: using connection 00000000068403F0
[7508427.904752] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream connect: -4
[7508427.905510] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream send request
[7508427.905572] 2012/06/24 07:37:30 [debug] 23293#0: *1 chain writer buf fl:0 s:137
[7508427.905632] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC540:16
[7508427.905678] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC590:16
[7508427.905717] 2012/06/24 07:37:30 [debug] 23293#0: *1 chain writer in: 00000000069EC540
[7508427.905821] 2012/06/24 07:37:30 [debug] 23293#0: *1 writev: 137
[7508427.905865] 2012/06/24 07:37:30 [debug] 23293#0: *1 chain writer out: 0000000000000000
[7508427.905917] 2012/06/24 07:37:30 [debug] 23293#0: *1 event timer add: 9: 60000:1340516310527
[7508427.906551] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream process header
[7508427.906623] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EC5E0:4096
[7508427.906675] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069ED620:16
[7508427.906725] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069ED670:384
[7508427.906769] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069ED830:16
[7508427.906843] 2012/06/24 07:37:30 [debug] 23293#0: *1 recv: fd:9 26 of 4096
[7508427.906897] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture header filter, uri "/redis"
[7508427.906931] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capturing response body
[7508427.907290] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069ED880:16
[7508427.907338] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069ED8D0:16
[7508427.907385] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069ED920:80
[7508427.907429] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069ED9B0:16
[7508427.921818] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream process non buffered downstream
[7508427.921863] 2012/06/24 07:37:30 [debug] 23293#0: *1 http output filter "/redis?3"
[7508427.921901] 2012/06/24 07:37:30 [debug] 23293#0: *1 http copy filter: "/redis?3"
[7508427.921959] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EDA00:104
[7508427.922003] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EDAB0:16
[7508427.922056] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture body filter, uri "/redis"
[7508427.922096] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture body filter capturing response body, uri "/redis"
[7508427.923679] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua reuse free buf chain, but reallocate memory because 26 >= 8, cl:00000000069E8130, p:00000000069E82B0
[7508427.924474] 2012/06/24 07:37:30 [debug] 23293#0: *1 free: 00000000069E82B0
[7508427.924949] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EDB00:26
[7508427.924997] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EDB60:16
[7508427.925948] 2012/06/24 07:37:30 [debug] 23293#0: *1 http copy filter: 0 "/redis?3"
[7508427.925996] 2012/06/24 07:37:30 [debug] 23293#0: *1 finalize http upstream request: 0
[7508427.926033] 2012/06/24 07:37:30 [debug] 23293#0: *1 finalize http redis2 request
[7508427.926066] 2012/06/24 07:37:30 [debug] 23293#0: *1 free keepalive peer
[7508427.926114] 2012/06/24 07:37:30 [debug] 23293#0: *1 free keepalive peer: saving connection 00000000068403F0
[7508427.926157] 2012/06/24 07:37:30 [debug] 23293#0: *1 event timer del: 9: 1340516310527
[7508427.926218] 2012/06/24 07:37:30 [debug] 23293#0: *1 free rr peer 1 0
[7508427.926277] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EDBB0:80
[7508427.926322] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EDC40:16
[7508427.926363] 2012/06/24 07:37:30 [debug] 23293#0: *1 http output filter "/redis?3"
[7508427.926399] 2012/06/24 07:37:30 [debug] 23293#0: *1 http copy filter: "/redis?3"
[7508427.926439] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture body filter, uri "/redis"
[7508427.926479] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture body filter capturing response body, uri "/redis"
[7508427.926523] 2012/06/24 07:37:30 [debug] 23293#0: *1 http copy filter: 0 "/redis?3"
[7508427.926568] 2012/06/24 07:37:30 [debug] 23293#0: *1 http finalize request: 0, "/redis?3" a:1, c:3
[7508427.926613] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run post subrequest handler: rc:0, waiting:0, done:0
[7508427.926649] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua restoring write event handler
[7508427.926698] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EDC90:26
[7508427.926743] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EDCF0:16
[7508427.926803] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EDD40:16
[7508427.926847] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EDD90:16
[7508427.926887] 2012/06/24 07:37:30 [debug] 23293#0: *1 http wake parent request: "/vote?questionid=1&answerid=1"
[7508427.927313] 2012/06/24 07:37:30 [debug] 23293#0: *1 http finalize request: -4, "/redis?3" a:0, c:2
[7508427.927355] 2012/06/24 07:37:30 [debug] 23293#0: *1 http request count:2 blk:0
[7508427.927397] 2012/06/24 07:37:30 [debug] 23293#0: *1 http posted request: "/vote?questionid=1&answerid=1"
[7508427.927431] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run write event handler
[7508427.927471] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run subrequests done, resuming lua thread
[7508427.927506] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua handle subrequest responses
[7508427.927657] 2012/06/24 07:37:30 [debug] 23293#0: *1 free: 00000000069EDC90
[7508427.927791] 2012/06/24 07:37:30 [debug] 23293#0: *1 free: 00000000069E9B50
[7508427.927834] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run thread
[7508427.938021] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EEEC0:32
[7508427.938073] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EEF20:16
[7508427.938180] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EEF70:48
[7508427.938237] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EEFE0:16
[7508427.938288] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF030:80
[7508427.938332] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF0C0:16
[7508427.938379] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF110:83
[7508427.938422] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF1B0:16
[7508427.938470] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF200:16
[7508427.938514] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF250:16
[7508427.938566] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF2A0:8
[7508427.938610] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF2F0:16
[7508427.938664] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF340:16
[7508427.938708] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF390:16
[7508427.938755] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF3E0:280
[7508427.938798] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF540:16
[7508427.938850] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EF590:1264
[7508427.938893] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EFAC0:16
[7508427.938945] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EFB10:432
[7508427.938989] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EFD00:16
[7508427.939088] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069EFD50:960
[7508427.939133] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0150:16
[7508427.939176] 2012/06/24 07:37:30 [debug] 23293#0: *1 http subrequest "/redis?2"
[7508427.939226] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F01A0:24
[7508427.939270] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0200:16
[7508427.939317] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0250:16
[7508427.939360] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F02A0:16
[7508427.939411] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F02F0:960
[7508427.939454] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F06F0:16
[7508427.939503] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0740:14
[7508427.939546] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0790:16
[7508427.939597] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F07E0:20
[7508427.939640] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0840:16
[7508427.939708] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0890:384
[7508427.939752] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0A50:16
[7508427.939811] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua resume returned 1
[7508427.939844] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua thread yielded
[7508427.939881] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run thread returned -2
[7508427.939919] 2012/06/24 07:37:30 [debug] 23293#0: *1 http posted request: "/redis?2"
[7508427.939958] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 0
[7508427.940023] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 1
[7508427.940079] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: "/"
[7508427.940118] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: "redis"
[7508427.940159] 2012/06/24 07:37:30 [debug] 23293#0: *1 test location: ~ "\.php$"
[7508427.940215] 2012/06/24 07:37:30 [debug] 23293#0: *1 using configuration "/redis"
[7508427.940258] 2012/06/24 07:37:30 [debug] 23293#0: *1 http cl:83 max:1048576
[7508427.940294] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 3
[7508427.940330] 2012/06/24 07:37:30 [debug] 23293#0: *1 rewrite phase: 4
[7508427.940367] 2012/06/24 07:37:30 [debug] 23293#0: *1 post rewrite phase: 5
[7508427.940402] 2012/06/24 07:37:30 [debug] 23293#0: *1 generic phase: 6
[7508427.940439] 2012/06/24 07:37:30 [debug] 23293#0: *1 generic phase: 7
[7508427.940499] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0AA0:832
[7508427.940544] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0E20:16
[7508427.940597] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0E70:64
[7508427.940640] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0EF0:16
[7508427.940680] 2012/06/24 07:37:30 [debug] 23293#0: *1 http init upstream, client timer: 0
[7508427.940745] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0F40:83
[7508427.940796] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F0FE0:16
[7508427.940847] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1030:83
[7508427.940891] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F10D0:16
[7508427.940938] 2012/06/24 07:37:30 [debug] 23293#0: *1 http script var: "*4
[7508427.940940] $7
[7508427.940941] hincrby
[7508427.940942] $10
[7508427.940943] question_1
[7508427.940944] $1
[7508427.940944] 1
[7508427.940945] $2
[7508427.940946] -1
[7508427.940947] *2
[7508427.940948] $7
[7508427.940949] hgetall
[7508427.940950] $10
[7508427.940951] question_1
[7508427.940952] "
[7508427.941008] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1120:1
[7508427.941051] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1170:16
[7508427.941090] 2012/06/24 07:37:30 [debug] 23293#0: *1 http script var: "2"
[7508427.941141] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F11C0:80
[7508427.941184] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1250:16
[7508427.941230] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F12A0:83
[7508427.941273] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1340:16
[7508427.941321] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1390:16
[7508427.941364] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F13E0:16
[7508427.941401] 2012/06/24 07:37:30 [debug] 23293#0: *1 http redis2 request: ""
[7508427.941446] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1430:40
[7508427.941489] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F14A0:16
[7508427.941534] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F14F0:56
[7508427.941577] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1570:16
[7508427.941623] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F15C0:24
[7508427.941666] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1620:16
[7508427.941705] 2012/06/24 07:37:30 [debug] 23293#0: *1 http cleanup add: 00000000069F15C0
[7508427.941739] 2012/06/24 07:37:30 [debug] 23293#0: *1 init keepalive peer
[7508427.941783] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1670:64
[7508427.941826] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F16F0:16
[7508427.941873] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1740:32
[7508427.941915] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F17A0:16
[7508427.941960] 2012/06/24 07:37:30 [debug] 23293#0: *1 get keepalive peer
[7508427.942001] 2012/06/24 07:37:30 [debug] 23293#0: *1 get keepalive peer: using connection 00000000068403F0
[7508427.942040] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream connect: -4
[7508427.942078] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream send request
[7508427.942131] 2012/06/24 07:37:30 [debug] 23293#0: *1 chain writer buf fl:0 s:83
[7508427.942179] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F17F0:16
[7508427.942223] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1840:16
[7508427.942262] 2012/06/24 07:37:30 [debug] 23293#0: *1 chain writer in: 00000000069F17F0
[7508427.942358] 2012/06/24 07:37:30 [debug] 23293#0: *1 writev: 83
[7508427.942401] 2012/06/24 07:37:30 [debug] 23293#0: *1 chain writer out: 0000000000000000
[7508427.942449] 2012/06/24 07:37:30 [debug] 23293#0: *1 event timer add: 9: 60000:1340516310527
[7508427.942489] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream process header
[7508427.942546] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F1890:4096
[7508427.942591] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F28D0:16
[7508427.942638] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2920:384
[7508427.942682] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2AE0:16
[7508427.942753] 2012/06/24 07:37:30 [debug] 23293#0: *1 recv: fd:9 22 of 4096
[7508427.942804] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture header filter, uri "/redis"
[7508427.942838] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capturing response body
[7508427.942903] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2B30:16
[7508427.942947] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2B80:16
[7508427.942993] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2BD0:80
[7508427.943036] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2C60:16
[7508427.943107] 2012/06/24 07:37:30 [debug] 23293#0: *1 http upstream process non buffered downstream
[7508427.943145] 2012/06/24 07:37:30 [debug] 23293#0: *1 http output filter "/redis?2"
[7508427.943182] 2012/06/24 07:37:30 [debug] 23293#0: *1 http copy filter: "/redis?2"
[7508427.943230] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2CB0:104
[7508427.943274] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2D60:16
[7508427.943323] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture body filter, uri "/redis"
[7508427.943364] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture body filter capturing response body, uri "/redis"
[7508427.944088] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua reuse free buf memory 26 >= 22, cl:00000000069E8130, p:00000000069EDB00
[7508427.944498] 2012/06/24 07:37:30 [debug] 23293#0: *1 http copy filter: 0 "/redis?2"
[7508427.944546] 2012/06/24 07:37:30 [debug] 23293#0: *1 finalize http upstream request: 0
[7508427.944583] 2012/06/24 07:37:30 [debug] 23293#0: *1 finalize http redis2 request
[7508427.944616] 2012/06/24 07:37:30 [debug] 23293#0: *1 free keepalive peer
[7508427.944662] 2012/06/24 07:37:30 [debug] 23293#0: *1 free keepalive peer: saving connection 00000000068403F0
[7508427.944706] 2012/06/24 07:37:30 [debug] 23293#0: *1 event timer del: 9: 1340516310527
[7508427.944765] 2012/06/24 07:37:30 [debug] 23293#0: *1 free rr peer 1 0
[7508427.944824] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2DB0:80
[7508427.944868] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2E40:16
[7508427.944909] 2012/06/24 07:37:30 [debug] 23293#0: *1 http output filter "/redis?2"
[7508427.944946] 2012/06/24 07:37:30 [debug] 23293#0: *1 http copy filter: "/redis?2"
[7508427.944986] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture body filter, uri "/redis"
[7508427.945025] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua capture body filter capturing response body, uri "/redis"
[7508427.945069] 2012/06/24 07:37:30 [debug] 23293#0: *1 http copy filter: 0 "/redis?2"
[7508427.945114] 2012/06/24 07:37:30 [debug] 23293#0: *1 http finalize request: 0, "/redis?2" a:1, c:3
[7508427.945159] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run post subrequest handler: rc:0, waiting:0, done:0
[7508427.945195] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua restoring write event handler
[7508427.945244] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2E90:22
[7508427.945287] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2EF0:16
[7508427.945348] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2F40:16
[7508427.945391] 2012/06/24 07:37:30 [debug] 23293#0: *1 malloc: 00000000069F2F90:16
[7508427.945431] 2012/06/24 07:37:30 [debug] 23293#0: *1 http wake parent request: "/vote?questionid=1&answerid=1"
[7508427.945481] 2012/06/24 07:37:30 [debug] 23293#0: *1 http finalize request: -4, "/redis?2" a:0, c:2
[7508427.945520] 2012/06/24 07:37:30 [debug] 23293#0: *1 http request count:2 blk:0
[7508427.945561] 2012/06/24 07:37:30 [debug] 23293#0: *1 http posted request: "/vote?questionid=1&answerid=1"
[7508427.945596] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run write event handler
[7508427.945635] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run subrequests done, resuming lua thread
[7508427.945669] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua handle subrequest responses
[7508427.945828] 2012/06/24 07:37:30 [debug] 23293#0: *1 free: 00000000069F2E90
[7508427.945950] 2012/06/24 07:37:30 [debug] 23293#0: *1 free: 00000000069EEEC0
[7508427.945993] 2012/06/24 07:37:30 [debug] 23293#0: *1 lua run thread

agentzh · 2012-06-24T05:58:47Z

Hmm, I still need more information :P

So the crash happens on the ngx.print line in the following lines of
your Lua code?

local ret = {success = true, data = {}}
local reply = replies[3]

for i = 1, #reply, 2 do
ngx.print(reply[i], reply[i+1])
ret.data[ reply[i] ] = reply[i+1]
end

And could you try dumping out the reply[i] and reply[i+1] arguments using JSON?

Also, can you reproduce the crash with LuaJIT 2.0? You can enable
LuaJIT 2.0 in your ngx_openresty build by passing the --with-luajit
configure option, BTW.

Thanks!
-agentzh

sztanpet · 2012-06-24T06:09:13Z

yes, here is the valgrind output with luajit

[07:37](/home/sztanpet/openresty/nginx/sbin)# valgrind  --leak-check=full ./nginx
==30156== Memcheck, a memory error detector
==30156== Copyright (C) 2002-2010, and GNU GPL'd, by Julian Seward et al.
==30156== Using Valgrind-3.6.1 and LibVEX; rerun with -h for copyright info
==30156== Command: ./nginx
==30156==
==30156== Invalid read of size 4
==30156==    at 0x54B7AF5: lj_str_new (lj_str.c:54)
==30156==    by 0x54C035A: lua_pushlstring (lj_api.c:589)
==30156==    by 0x4D84B0: ngx_http_lua_parse_args (ngx_http_lua_args.c:314)
==30156==    by 0x4D7EBE: ngx_http_lua_ngx_req_get_uri_args (ngx_http_lua_args.c:120)
==30156==    by 0x54B21E6: lj_BC_FUNCC (in /home/sztanpet/openresty/luajit/lib/libluajit-5.1.so.2.0.0)
==30156==    by 0x4E131D: ngx_http_lua_run_thread (ngx_http_lua_util.c:775)
==30156==    by 0x4E535F: ngx_http_lua_content_by_chunk (ngx_http_lua_contentby.c:93)
==30156==    by 0x4E57EA: ngx_http_lua_content_handler_file (ngx_http_lua_contentby.c:247)
==30156==    by 0x4E55B3: ngx_http_lua_content_handler (ngx_http_lua_contentby.c:176)
==30156==    by 0x455F85: ngx_http_core_content_phase (ngx_http_core_module.c:1377)
==30156==    by 0x454B6F: ngx_http_core_run_phases (ngx_http_core_module.c:872)
==30156==    by 0x454AE6: ngx_http_handler (ngx_http_core_module.c:855)
==30156==  Address 0x6e505e6 is 22 bytes inside a block of size 23 alloc'd
==30156==    at 0x4C267CE: malloc (vg_replace_malloc.c:236)
==30156==    by 0x442427: ngx_alloc (ngx_alloc.c:22)
==30156==    by 0x41B582: ngx_malloc (ngx_palloc.c:119)
==30156==    by 0x41B615: ngx_palloc (ngx_palloc.c:140)
==30156==    by 0x4D7E42: ngx_http_lua_ngx_req_get_uri_args (ngx_http_lua_args.c:111)
==30156==    by 0x54B21E6: lj_BC_FUNCC (in /home/sztanpet/openresty/luajit/lib/libluajit-5.1.so.2.0.0)
==30156==    by 0x4E131D: ngx_http_lua_run_thread (ngx_http_lua_util.c:775)
==30156==    by 0x4E535F: ngx_http_lua_content_by_chunk (ngx_http_lua_contentby.c:93)
==30156==    by 0x4E57EA: ngx_http_lua_content_handler_file (ngx_http_lua_contentby.c:247)
==30156==    by 0x4E55B3: ngx_http_lua_content_handler (ngx_http_lua_contentby.c:176)
==30156==    by 0x455F85: ngx_http_core_content_phase (ngx_http_core_module.c:1377)
==30156==    by 0x454B6F: ngx_http_core_run_phases (ngx_http_core_module.c:872)
==30156==
==30156== Conditional jump or move depends on uninitialised value(s)
==30156==    at 0x54B7AF9: lj_str_new (lj_str.c:54)
==30156==    by 0x54B8246: lj_str_fromnum (lj_str.c:281)
==30156==    by 0x54BAADC: lj_meta_cat (lj_meta.c:233)
==30156==    by 0x54B1284: lj_BC_CAT (in /home/sztanpet/openresty/luajit/lib/libluajit-5.1.so.2.0.0)
==30156==    by 0x4E131D: ngx_http_lua_run_thread (ngx_http_lua_util.c:775)
==30156==    by 0x4E535F: ngx_http_lua_content_by_chunk (ngx_http_lua_contentby.c:93)
==30156==    by 0x4E57EA: ngx_http_lua_content_handler_file (ngx_http_lua_contentby.c:247)
==30156==    by 0x4E55B3: ngx_http_lua_content_handler (ngx_http_lua_contentby.c:176)
==30156==    by 0x455F85: ngx_http_core_content_phase (ngx_http_core_module.c:1377)
==30156==    by 0x454B6F: ngx_http_core_run_phases (ngx_http_core_module.c:872)
==30156==    by 0x454AE6: ngx_http_handler (ngx_http_core_module.c:855)
==30156==    by 0x4627C5: ngx_http_process_request (ngx_http_request.c:1672)
==30156==
==30156== Conditional jump or move depends on uninitialised value(s)
==30156==    at 0x54B7AF9: lj_str_new (lj_str.c:54)
==30156==    by 0x54B8246: lj_str_fromnum (lj_str.c:281)
==30156==    by 0x54C16B7: lua_tolstring (lj_api.c:439)
==30156==    by 0x77CDD6B: redis_build_query (redis-parser.c:566)
==30156==    by 0x54B21E6: lj_BC_FUNCC (in /home/sztanpet/openresty/luajit/lib/libluajit-5.1.so.2.0.0)
==30156==    by 0x4E131D: ngx_http_lua_run_thread (ngx_http_lua_util.c:775)
==30156==    by 0x4E535F: ngx_http_lua_content_by_chunk (ngx_http_lua_contentby.c:93)
==30156==    by 0x4E57EA: ngx_http_lua_content_handler_file (ngx_http_lua_contentby.c:247)
==30156==    by 0x4E55B3: ngx_http_lua_content_handler (ngx_http_lua_contentby.c:176)
==30156==    by 0x455F85: ngx_http_core_content_phase (ngx_http_core_module.c:1377)
==30156==    by 0x454B6F: ngx_http_core_run_phases (ngx_http_core_module.c:872)
==30156==    by 0x454AE6: ngx_http_handler (ngx_http_core_module.c:855)
==30156==
==30156== Conditional jump or move depends on uninitialised value(s)
==30156==    at 0x54B7AF9: lj_str_new (lj_str.c:54)
==30156==    by 0x54B8246: lj_str_fromnum (lj_str.c:281)
==30156==    by 0x54C18C7: luaL_checklstring (lj_api.c:458)
==30156==    by 0x77CDEB3: redis_build_query (redis-parser.c:609)
==30156==    by 0x54B21E6: lj_BC_FUNCC (in /home/sztanpet/openresty/luajit/lib/libluajit-5.1.so.2.0.0)
==30156==    by 0x4E131D: ngx_http_lua_run_thread (ngx_http_lua_util.c:775)
==30156==    by 0x4E535F: ngx_http_lua_content_by_chunk (ngx_http_lua_contentby.c:93)
==30156==    by 0x4E57EA: ngx_http_lua_content_handler_file (ngx_http_lua_contentby.c:247)
==30156==    by 0x4E55B3: ngx_http_lua_content_handler (ngx_http_lua_contentby.c:176)
==30156==    by 0x455F85: ngx_http_core_content_phase (ngx_http_core_module.c:1377)
==30156==    by 0x454B6F: ngx_http_core_run_phases (ngx_http_core_module.c:872)
==30156==    by 0x454AE6: ngx_http_handler (ngx_http_core_module.c:855)
==30156==
==30156== Conditional jump or move depends on uninitialised value(s)
==30156==    at 0x54B7AF9: lj_str_new (lj_str.c:54)
==30156==    by 0x54B8246: lj_str_fromnum (lj_str.c:281)
==30156==    by 0x54C16B7: lua_tolstring (lj_api.c:439)
==30156==    by 0x54FFCEE: luaL_addvalue (lib_aux.c:175)
==30156==    by 0x5504817: lj_cf_table_concat (lib_table.c:161)
==30156==    by 0x54B21E6: lj_BC_FUNCC (in /home/sztanpet/openresty/luajit/lib/libluajit-5.1.so.2.0.0)
==30156==    by 0x4E131D: ngx_http_lua_run_thread (ngx_http_lua_util.c:775)
==30156==    by 0x4E2061: ngx_http_lua_wev_handler (ngx_http_lua_util.c:1191)
==30156==    by 0x4E537E: ngx_http_lua_content_wev_handler (ngx_http_lua_contentby.c:100)
==30156==    by 0x462CB1: ngx_http_run_posted_requests (ngx_http_request.c:1859)
==30156==    by 0x4780F7: ngx_http_upstream_handler (ngx_http_upstream.c:921)
==30156==    by 0x44A601: ngx_epoll_process_events (ngx_epoll_module.c:679)
==30156==
==30156== Conditional jump or move depends on uninitialised value(s)
==30156==    at 0x54B7AF9: lj_str_new (lj_str.c:54)
==30156==    by 0x54C035A: lua_pushlstring (lj_api.c:589)
==30156==    by 0x4D0242: ngx_http_lua_handle_subreq_responses (ngx_http_lua_subrequest.c:1167)
==30156==    by 0x4E1F70: ngx_http_lua_wev_handler (ngx_http_lua_util.c:1158)
==30156==    by 0x4E537E: ngx_http_lua_content_wev_handler (ngx_http_lua_contentby.c:100)
==30156==    by 0x462CB1: ngx_http_run_posted_requests (ngx_http_request.c:1859)
==30156==    by 0x4780F7: ngx_http_upstream_handler (ngx_http_upstream.c:921)
==30156==    by 0x44A601: ngx_epoll_process_events (ngx_epoll_module.c:679)
==30156==    by 0x43B99B: ngx_process_events_and_timers (ngx_event.c:246)
==30156==    by 0x447200: ngx_single_process_cycle (ngx_process_cycle.c:312)
==30156==    by 0x4188C7: main (nginx.c:409)
==30156==
==30156==
==30156== HEAP SUMMARY:
==30156==     in use at exit: 2,305,819 bytes in 6,024 blocks
==30156==   total heap usage: 7,003 allocs, 979 frees, 2,439,809 bytes allocated
==30156==
==30156== 292 (52 direct, 240 indirect) bytes in 1 blocks are definitely lost in loss record 1,454 of 1,651
==30156==    at 0x4C267CE: malloc (vg_replace_malloc.c:236)
==30156==    by 0x67064CB: nss_parse_service_list (nsswitch.c:540)
==30156==    by 0x6706CA5: __nss_database_lookup (nsswitch.c:134)
==30156==    by 0x6F9732F: ???
==30156==    by 0x6F98384: ???
==30156==    by 0x66C555C: getpwnam_r@@GLIBC_2.2.5 (getXXbyYY_r.c:253)
==30156==    by 0x66C4F3F: getpwnam (getXXbyYY.c:117)
==30156==    by 0x41A05D: ngx_set_user (nginx.c:1147)
==30156==    by 0x431EE3: ngx_conf_handler (ngx_conf_file.c:394)
==30156==    by 0x431A77: ngx_conf_parse (ngx_conf_file.c:244)
==30156==    by 0x42E626: ngx_init_cycle (ngx_cycle.c:268)
==30156==    by 0x41862F: main (nginx.c:333)
==30156==
==30156== 292 (52 direct, 240 indirect) bytes in 1 blocks are definitely lost in loss record 1,455 of 1,651
==30156==    at 0x4C267CE: malloc (vg_replace_malloc.c:236)
==30156==    by 0x67064CB: nss_parse_service_list (nsswitch.c:540)
==30156==    by 0x6706CA5: __nss_database_lookup (nsswitch.c:134)
==30156==    by 0x6F9640F: ???
==30156==    by 0x6F96EDC: ???
==30156==    by 0x66C42AC: getgrnam_r@@GLIBC_2.2.5 (getXXbyYY_r.c:253)
==30156==    by 0x66C385F: getgrnam (getXXbyYY.c:117)
==30156==    by 0x41A0FA: ngx_set_user (nginx.c:1159)
==30156==    by 0x431EE3: ngx_conf_handler (ngx_conf_file.c:394)
==30156==    by 0x431A77: ngx_conf_parse (ngx_conf_file.c:244)
==30156==    by 0x42E626: ngx_init_cycle (ngx_cycle.c:268)
==30156==    by 0x41862F: main (nginx.c:333)
==30156==
==30156== LEAK SUMMARY:
==30156==    definitely lost: 104 bytes in 2 blocks
==30156==    indirectly lost: 480 bytes in 20 blocks
==30156==      possibly lost: 0 bytes in 0 blocks
==30156==    still reachable: 2,305,235 bytes in 6,002 blocks
==30156==         suppressed: 0 bytes in 0 blocks
==30156== Reachable blocks (those to which a pointer was found) are not shown.
==30156== To see them, rerun with: --leak-check=full --show-reachable=yes
==30156==
==30156== For counts of detected and suppressed errors, rerun with: -v
==30156== Use --track-origins=yes to see where uninitialised values come from
==30156== ERROR SUMMARY: 18 errors from 8 contexts (suppressed: 7 from 7)
Aborted

and the json dump of reply[i] and reply[i+1] is the following

local json = require "cjson"
for i = 1, #reply, 2 do
  --ngx.print(reply[i], reply[i+1])
  ngx.say( json.encode( reply[i] ) )
  ngx.say( json.encode( reply[i+1] ) )
  ret.data[ reply[i] ] = reply[i+1]
end

with the following code, it does not segfault
and this is the output

["1","5"] -- this seems wrong, this should be the key, 1
5

agentzh · 2012-06-24T06:21:10Z

Hello!

On Sun, Jun 24, 2012 at 2:09 PM, sztanpet
reply@reply.github.com
wrote:

yes, here is the valgrind output with luajit
[...]
==30156== ERROR SUMMARY: 18 errors from 8 contexts (suppressed: 7 from 7)
Aborted

Valgrind says the nginx process is aborted. Then there should be an
assertion failure in your nginx's error.log. Can you check it out?

Also, please use gdb to obtain the backtrace for this assertion failure. Thanks!

and the json dump of reply[i] and reply[i+1] is the following

local json = require "cjson"
for i = 1, #reply, 2 do
--ngx.print(reply[i], reply[i+1])
ngx.say( json.encode( reply[i] ) )
ngx.say( json.encode( reply[i+1] ) )
ret.data[ reply[i] ] = reply[i+1]
end

with the following code, it does not segfault
and this is the output

["1","5"] -- this seems wrong, this should be the key, 1
5

Can you output the "replies" table with cjson.encode right after
calling parse_replies? That is, right after the line

local replies = parser.parse_replies(result.body, #requests)

Also, what is exactly in result.body? Can you output it as a string directly?

Thanks!
-agentzh

sztanpet · 2012-06-24T06:39:12Z

Program received signal SIGABRT, Aborted.
0x00007ffff62c0065 in *__GI_raise (sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
64      ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
        in ../nptl/sysdeps/unix/sysv/linux/raise.c
(gdb) bt
#0  0x00007ffff62c0065 in *__GI_raise (sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  0x00007ffff62c12ff in *__GI_abort () at abort.c:92
#2  0x00007ffff62b91e1 in *__GI___assert_fail (assertion=0x7ffff7547e15 "(((t)->it) == (~11u))", file=<optimized out>,
    line=833, function=0x7ffff7547bd0 "lua_next") at assert.c:81
#3  0x00007ffff74f7a51 in lua_next (L=0x4000c770, idx=<optimized out>) at lj_api.c:833
#4  0x00000000004d4708 in ngx_http_lua_calc_strlen_in_table (L=0x4000c770, arg_i=1, strict=0)
    at ../ngx_lua-0.5.0rc30/src/ngx_http_lua_output.c:253
#5  0x00000000004d4187 in ngx_http_lua_ngx_echo (L=0x4000c770, newline=0)
    at ../ngx_lua-0.5.0rc30/src/ngx_http_lua_output.c:108
#6  0x00000000004d3fb7 in ngx_http_lua_ngx_print (L=0x4000c770) at ../ngx_lua-0.5.0rc30/src/ngx_http_lua_output.c:24
#7  0x00007ffff74e91e7 in lj_BC_FUNCC () from /home/sztanpet/openresty/luajit/lib/libluajit-5.1.so.2
#8  0x00000000004e131e in ngx_http_lua_run_thread (L=0x40000378, r=0x7a9ec0, ctx=0x7c40f0, nret=1)
    at ../ngx_lua-0.5.0rc30/src/ngx_http_lua_util.c:775
#9  0x00000000004e2062 in ngx_http_lua_wev_handler (r=0x7a9ec0) at ../ngx_lua-0.5.0rc30/src/ngx_http_lua_util.c:1191
#10 0x00000000004e537f in ngx_http_lua_content_wev_handler (r=0x7a9ec0)
    at ../ngx_lua-0.5.0rc30/src/ngx_http_lua_contentby.c:100
#11 0x0000000000462cb2 in ngx_http_run_posted_requests (c=0x7ffff7ecc0d0) at src/http/ngx_http_request.c:1859
#12 0x00000000004780f8 in ngx_http_upstream_handler (ev=0x7ffff7e63148) at src/http/ngx_http_upstream.c:921
#13 0x000000000044a602 in ngx_epoll_process_events (cycle=0x78d3f0, timer=18446744073709551615, flags=0)
    at src/event/modules/ngx_epoll_module.c:679
#14 0x000000000043b99c in ngx_process_events_and_timers (cycle=0x78d3f0) at src/event/ngx_event.c:246
#15 0x0000000000447201 in ngx_single_process_cycle (cycle=0x78d3f0) at src/os/unix/ngx_process_cycle.c:312
#16 0x00000000004188c8 in main (argc=1, argv=0x7fffffffe2b8) at src/core/nginx.c:409

the result.body

:5
*2
$1
1
$1
5

the json.encode( replies )

[[5,3],[["1","5"],5]]

EDIT: the json encode right after parsing, and no, there is nothing extra in the error log, I can paste it again if you want

agentzh · 2012-06-24T08:16:21Z

Hello!

On Sun, Jun 24, 2012 at 2:39 PM, sztanpet
reply@reply.github.com
wrote:

Program received signal SIGABRT, Aborted.
0x00007ffff62c0065 in *__GI_raise (sig=) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
64 ../nptl/sysdeps/unix/sysv/linux/raise.c: No such file or directory.
in ../nptl/sysdeps/unix/sysv/linux/raise.c
(gdb) bt
#0 0x00007ffff62c0065 in *__GI_raise (sig=) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1 0x00007ffff62c12ff in *__GI_abort () at abort.c:92
#2 0x00007ffff62b91e1 in *__GI___assert_fail (assertion=0x7ffff7547e15 "(((t)->it) == (~11u))", file=,
line=833, function=0x7ffff7547bd0 "lua_next") at assert.c:81
#3 0x00007ffff74f7a51 in lua_next (L=0x4000c770, idx=) at lj_api.c:833

This backtrace is invaluable! I've just reproduced this on my side and
it is indeed a very silly bug. I'll fix it later today and send you a
new version to try :)

Thank you very much!
-agentzh

sztanpet · 2012-06-24T08:22:51Z

thanks for your time and the awesome software
was this issue related to what the ticket is about? :D

agentzh · 2012-06-24T09:47:40Z

Hello!

On Sun, Jun 24, 2012 at 4:22 PM, sztanpet
reply@reply.github.com
wrote:

thanks for your time and the awesome software
was this issue related to what the ticket is about? :D

I don't think so. It's an issue in ngx.print()/ngx.say() when table
arguments are given.

Best regards,
-agentzh

…yped arguments were given. thanks sztanpet for reporting this in github issue #54.

agentzh · 2012-06-24T14:05:18Z

Hello!

On Sun, Jun 24, 2012 at 4:16 PM, agentzh agentzh@gmail.com wrote:

I've just reproduced this on my side and
it is indeed a very silly bug. I'll fix it later today and send you a
new version to try :)

I've just committed a patch for this issue to ngx_lua's git master branch:

https://github.com/chaoslawful/lua-nginx-module/commit/0178d4e

Could you please try out this patch (or the git master HEAD) on your
side? This fix will be included in the next version of ngx_lua and
ngx_openresty :)

Thanks!
-agentzh

agentzh · 2012-06-24T15:44:35Z

Hello!

On Sun, Jun 24, 2012 at 10:05 PM, agentzh agentzh@gmail.com wrote:

I've just committed a patch for this issue to ngx_lua's git master branch:

0178d4e

Could you please try out this patch (or the git master HEAD) on your
side? This fix will be included in the next version of ngx_lua and
ngx_openresty :)

To make your life easier, I've just put a new (rc) version of the
ngx_openresty tarball including the fix here for you to try:

http://agentzh.org/misc/nginx/ngx_openresty-1.2.1.3rc1.tar.gz

Thanks!
-agentzh

sztanpet · 2012-06-24T16:01:06Z

yes, the segfault is gone but this parsed response seems wrong for this body:

:5
*2
$1
1
$1
5

[[5,3],[["1","5"],5]]

is that table valid tho for the response? the parsing seems a bit off or my code is buggy, anyway that should probably be another ticket if its not on my end

agentzh · 2012-06-25T02:33:23Z

Hello!

On Mon, Jun 25, 2012 at 12:01 AM, sztanpet
reply@reply.github.com
wrote:

yes, the segfault is gone but this parsed response seems wrong for this body:

:5
*2
$1
1
$1
5

[[5,3],[["1","5"],5]]

is that table valid tho for the response?

Please provide a minimal example for this because it could be an issue
in your own Lua code :)

BTW, nowadays it's recommended to use the lua-resty-redis library that
is based on ngx_lua's cosocket API:

https://github.com/agentzh/lua-resty-redis

This is much simpler to use than the old approach you're using,
i.e., ngx.location.capture + ngx_redis2 + lua-redis-parser, and it's
also reported to be more efficient.

Best regards,
-agentzh

sztanpet · 2012-06-25T05:33:31Z

nope, nevermind it was on my end,
does lua-resty-redis support connection pools the same way location.capture does tho?

agentzh · 2012-06-25T05:38:54Z

Hello!

On Mon, Jun 25, 2012 at 1:33 PM, sztanpet
reply@reply.github.com
wrote:

does lua-resty-redis support connection pools the same way location.capture does tho?

Sure thing! Check out its set_keepalive method which puts the current
redis connection into the ngx_lua cosocket connection pools. It does
not use ngx_http_upstream_keepalive though. The ngx_lua module
implements its own.

Best regards,
-agentzh

…yped arguments were given. thanks sztanpet for reporting this in github issue openresty#54.

agentzh · 2012-09-27T18:37:45Z

Consider it resolved.

agentzh added a commit that referenced this issue Jun 24, 2012

bugfix: ngx.say and ngx.print might cause nginx to crash when table-t…

0178d4e

…yped arguments were given. thanks sztanpet for reporting this in github issue #54.

bakins pushed a commit to bakins/lua-nginx-module that referenced this issue Jun 30, 2012

bugfix: ngx.say and ngx.print might cause nginx to crash when table-t…

ca2a5c1

…yped arguments were given. thanks sztanpet for reporting this in github issue openresty#54.

agentzh closed this as completed Sep 27, 2012

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Issues with subrequests in Lua 5.1.4 #54

Issues with subrequests in Lua 5.1.4 #54

ghost commented Aug 26, 2011

agentzh commented Aug 26, 2011

ghost commented Aug 26, 2011

agentzh commented Nov 17, 2011

ghost commented Nov 17, 2011

agentzh commented Apr 19, 2012

sztanpet commented Jun 23, 2012

sztanpet commented Jun 23, 2012

sztanpet commented Jun 23, 2012

agentzh commented Jun 24, 2012

sztanpet commented Jun 24, 2012

sztanpet commented Jun 24, 2012

agentzh commented Jun 24, 2012

sztanpet commented Jun 24, 2012

agentzh commented Jun 24, 2012

sztanpet commented Jun 24, 2012

agentzh commented Jun 24, 2012

sztanpet commented Jun 24, 2012

agentzh commented Jun 24, 2012

sztanpet commented Jun 24, 2012

agentzh commented Jun 24, 2012

agentzh commented Jun 24, 2012

agentzh commented Jun 24, 2012

sztanpet commented Jun 24, 2012

agentzh commented Jun 25, 2012

sztanpet commented Jun 25, 2012

agentzh commented Jun 25, 2012

agentzh commented Sep 27, 2012

Issues with subrequests in Lua 5.1.4 #54

Issues with subrequests in Lua 5.1.4 #54

Comments

ghost commented Aug 26, 2011

agentzh commented Aug 26, 2011

ghost commented Aug 26, 2011

agentzh commented Nov 17, 2011

ghost commented Nov 17, 2011

agentzh commented Apr 19, 2012

sztanpet commented Jun 23, 2012

sztanpet commented Jun 23, 2012

sztanpet commented Jun 23, 2012

agentzh commented Jun 24, 2012

sztanpet commented Jun 24, 2012

sztanpet commented Jun 24, 2012

agentzh commented Jun 24, 2012

sztanpet commented Jun 24, 2012

agentzh commented Jun 24, 2012

sztanpet commented Jun 24, 2012

agentzh commented Jun 24, 2012

sztanpet commented Jun 24, 2012

agentzh commented Jun 24, 2012

sztanpet commented Jun 24, 2012

agentzh commented Jun 24, 2012

agentzh commented Jun 24, 2012

agentzh commented Jun 24, 2012

sztanpet commented Jun 24, 2012

agentzh commented Jun 25, 2012

sztanpet commented Jun 25, 2012

agentzh commented Jun 25, 2012

agentzh commented Sep 27, 2012