srcache SEGFAULT

[Shaun savage]

srcache crashed again.  I am sorry that I can not debug it more, tell me
where to look and I can do it.

I run it the first time, the value is not in cache. so it executes the
lua file

 I the lua file I am setting the cache value to a json string
{"skey":"0123456789ABCDEF","pkgid":5}

I call it again and it seg faults
18446744073709551615 = -ffffffff

GDB  print *in
the last is one byte before the start


$ uname -a
Linux svvsgo 2.6.38-11-generic #50-Ubuntu SMP Mon Sep 12 21:17:25 UTC
2011 x86_64 x86_64 x86_64 GNU/Linux

request
$curl -v -H "X-Auth-Token: 0123456789ABCDEF" http://localhost:9000/foo

************************** BT **********************************************

#1  0x00000000005039b9 in ngx_http_srcache_body_filter (r=0x836700,
    in=0x837918)
    at
modules/agentzh-srcache-nginx-module-06b7ab4/src/ngx_http_srcache_filter_module.c:407
#2  0x000000000041a1be in ngx_output_chain (ctx=0x837978, in=0x837918)
    at src/core/ngx_output_chain.c:65
#3  0x0000000000467ab8 in ngx_http_copy_filter (r=0x836700, in=0x837918)
    at src/http/ngx_http_copy_filter_module.c:141
#4  0x00000000004827c9 in ngx_http_range_body_filter (r=0x836700,
in=0x837918)
    at src/http/modules/ngx_http_range_filter_module.c:551
#5  0x0000000000453e1a in ngx_http_output_filter (r=0x836700, in=0x837918)
    at src/http/ngx_http_core_module.c:1867
#6  0x00000000004785ab in ngx_http_upstream_process_non_buffered_request (
    r=0x836700, do_write=1) at src/http/ngx_http_upstream.c:2400
#7  0x000000000047843e in
ngx_http_upstream_process_non_buffered_downstream (
    r=0x836700) at src/http/ngx_http_upstream.c:2348
#8  0x0000000000477a8a in ngx_http_upstream_send_response (r=0x836700,
---Type <return> to continue, or q <return> to quit---
    u=0x837270) at src/http/ngx_http_upstream.c:2120
#9  0x0000000000476897 in ngx_http_upstream_process_header (r=0x836700,
    u=0x837270) at src/http/ngx_http_upstream.c:1621
#10 0x0000000000475191 in ngx_http_upstream_handler (ev=0x7d79e8)
    at src/http/ngx_http_upstream.c:924
#11 0x0000000000446b50 in ngx_epoll_process_events (cycle=0x777e00,
timer=100,
    flags=1) at src/event/modules/ngx_epoll_module.c:635
#12 0x00000000004377e4 in ngx_process_events_and_timers (cycle=0x777e00)
    at src/event/ngx_event.c:245
#13 0x00000000004433d4 in ngx_single_process_cycle (cycle=0x777e00)
    at src/os/unix/ngx_process_cycle.c:311
#14 0x00000000004140c3 in main (argc=1, argv=0x7fffffffe638)
    at src/core/nginx.c:402
(gdb)


****************** LUA FILE ****************************
#!/usr/bin/env lua

local ngx = require("ngx")
local ndk = require("ndk")
local memcache = require('Memcached')
local json = require('json')


key = ngx.var.http_x_auth_token
-- hello
ngx.say( "Hello world", key);

local m = memcache.Connect()
m:set_encode(json.encode)
m:set_decode(json.decode)

sessinfo = { skey="0123456789ABCDEF",pkgid=5  }
ngx.say(sessinfo.skey,"=",key)

if sessinfo.skey == key then
    ngx.say(json.encode(sessinfo)," ",type(m))
    for k,v in pairs( m ) do ngx.say(k, type(v)) end
    m:set( key, sessinfo )
end


******************** CONFIG *************************

    location ~ ^/foo {
        charset utf-8;
        default_type text/plain;
        set $key $http_x_auth_token;
        srcache_fetch GET    /memc    $key;
        #srcache_store PUT /memc $key;

        #content_by_lua    "ngx.say(ngx.var.key)";
        content_by_lua_file "/var/www/nginx/hello.lua";
        #rewrite ^/foo /martin        last;
    }

*******************  error log *******************************
2011/09/27 20:23:01 [debug] 28469#0: accept on 0.0.0.0:9000, ready: 0
2011/09/27 20:23:01 [debug] 28469#0: posix_memalign:
00000000007D7C10:256 @16
2011/09/27 20:23:01 [debug] 28469#0: *3 accept: 127.0.0.1 fd:12
2011/09/27 20:23:01 [debug] 28469#0: *3 event timer add: 12:
900000:1317127081041
2011/09/27 20:23:01 [debug] 28469#0: *3 epoll add event: fd:12 op:1
ev:80000001
2011/09/27 20:23:01 [debug] 28469#0: *3 malloc: 00000000008102C0:1272
2011/09/27 20:23:01 [debug] 28469#0: *3 posix_memalign:
00000000007D7D20:256 @16
2011/09/27 20:23:01 [debug] 28469#0: *3 malloc: 0000000000785220:1024
2011/09/27 20:23:01 [debug] 28469#0: *3 posix_memalign:
0000000000785630:4096 @16
2011/09/27 20:23:01 [debug] 28469#0: *3 http process request line
2011/09/27 20:23:01 [debug] 28469#0: *3 recv: fd:12 190 of 1024
2011/09/27 20:23:01 [debug] 28469#0: *3 http request line: "GET /foo
HTTP/1.1"
2011/09/27 20:23:01 [debug] 28469#0: *3 http uri: "/foo"
2011/09/27 20:23:01 [debug] 28469#0: *3 http args: ""
2011/09/27 20:23:01 [debug] 28469#0: *3 http exten: ""
2011/09/27 20:23:01 [debug] 28469#0: *3 http process request header line
2011/09/27 20:23:01 [debug] 28469#0: *3 http header: "User-Agent:
curl/7.21.3 (x86_64-pc-linux-gnu) libcurl/7.21.3 OpenSSL/0.9.8o
zlib/1.2.3.4 libidn/1.18"
2011/09/27 20:23:01 [debug] 28469#0: *3 http header: "Host: localhost:9000"
2011/09/27 20:23:01 [debug] 28469#0: *3 http header: "Accept: */*"
2011/09/27 20:23:01 [debug] 28469#0: *3 http header: "X-Auth-Token:
0123456789ABCDEF"
2011/09/27 20:23:01 [debug] 28469#0: *3 http header done
2011/09/27 20:23:01 [debug] 28469#0: *3 event timer del: 12: 1317127081041
2011/09/27 20:23:01 [debug] 28469#0: *3 rewrite phase: 0
2011/09/27 20:23:01 [debug] 28469#0: *3 test location: "/"
2011/09/27 20:23:01 [debug] 28469#0: *3 test location: "lua"
2011/09/27 20:23:01 [debug] 28469#0: *3 test location: "doc"
2011/09/27 20:23:01 [debug] 28469#0: *3 test location: ~ "^/foo"
2011/09/27 20:23:01 [debug] 28469#0: *3 using configuration "^/foo"
2011/09/27 20:23:01 [debug] 28469#0: *3 http cl:-1 max:1048576
2011/09/27 20:23:01 [debug] 28469#0: *3 rewrite phase: 2
2011/09/27 20:23:01 [debug] 28469#0: *3 rewrite phase: 3
2011/09/27 20:23:01 [debug] 28469#0: *3 http script complex value
2011/09/27 20:23:01 [debug] 28469#0: *3 http script var: "0123456789ABCDEF"
2011/09/27 20:23:01 [debug] 28469#0: *3 http script set $key
2011/09/27 20:23:01 [debug] 28469#0: *3 post rewrite phase: 4
2011/09/27 20:23:01 [debug] 28469#0: *3 generic phase: 5
2011/09/27 20:23:01 [debug] 28469#0: *3 generic phase: 6
2011/09/27 20:23:01 [debug] 28469#0: *3 access phase: 7
2011/09/27 20:23:01 [debug] 28469#0: *3 access phase: 8
2011/09/27 20:23:01 [debug] 28469#0: *3 access phase: 9
2011/09/27 20:23:01 [debug] 28469#0: *3 access phase: 10
2011/09/27 20:23:01 [debug] 28469#0: *3 post access phase: 11
2011/09/27 20:23:01 [debug] 28469#0: *3 access phase: 12
2011/09/27 20:23:01 [debug] 28469#0: *3 http script var: "0123456789ABCDEF"
2011/09/27 20:23:01 [debug] 28469#0: *3 posix_memalign:
00000000008366E0:4096 @16
2011/09/27 20:23:01 [debug] 28469#0: *3 http subrequest
"/memc?0123456789ABCDEF"
2011/09/27 20:23:01 [debug] 28469#0: *3 http posted request:
"/memc?0123456789ABCDEF"
2011/09/27 20:23:01 [debug] 28469#0: *3 rewrite phase: 0
2011/09/27 20:23:01 [debug] 28469#0: *3 test location: "/"
2011/09/27 20:23:01 [debug] 28469#0: *3 test location: "lua"
2011/09/27 20:23:01 [debug] 28469#0: *3 test location: "new"
2011/09/27 20:23:01 [debug] 28469#0: *3 test location: "memc"
2011/09/27 20:23:01 [debug] 28469#0: *3 using configuration "=/memc"
2011/09/27 20:23:01 [debug] 28469#0: *3 http cl:-1 max:1048576
2011/09/27 20:23:01 [debug] 28469#0: *3 rewrite phase: 2
2011/09/27 20:23:01 [debug] 28469#0: *3 rewrite phase: 3
2011/09/27 20:23:01 [debug] 28469#0: *3 http script complex value
2011/09/27 20:23:01 [debug] 28469#0: *3 http script var: "0123456789ABCDEF"
2011/09/27 20:23:01 [debug] 28469#0: *3 http script set $memc_key
2011/09/27 20:23:01 [debug] 28469#0: *3 http script value: "300"
2011/09/27 20:23:01 [debug] 28469#0: *3 http script set $memc_exptime
2011/09/27 20:23:01 [debug] 28469#0: *3 post rewrite phase: 4
2011/09/27 20:23:01 [debug] 28469#0: *3 generic phase: 5
2011/09/27 20:23:01 [debug] 28469#0: *3 generic phase: 6
2011/09/27 20:23:01 [debug] 28469#0: *3 try files phase: 13
2011/09/27 20:23:01 [debug] 28469#0: *3 http init upstream, client timer: 0
2011/09/27 20:23:01 [debug] 28469#0: *3 epoll add event: fd:12 op:3
ev:80000005
2011/09/27 20:23:01 [debug] 28469#0: *3 http memcached request:
"0123456789ABCDEF"
2011/09/27 20:23:01 [debug] 28469#0: *3 posix_memalign:
00000000008376F0:4096 @16
2011/09/27 20:23:01 [debug] 28469#0: *3 http cleanup add: 00000000008376B0
2011/09/27 20:23:01 [debug] 28469#0: *3 init keepalive peer
2011/09/27 20:23:01 [debug] 28469#0: *3 get keepalive peer
2011/09/27 20:23:01 [debug] 28469#0: *3 get rr peer, try: 1
2011/09/27 20:23:01 [debug] 28469#0: *3 socket 14
2011/09/27 20:23:01 [debug] 28469#0: *3 epoll add connection: fd:14
ev:80000005
2011/09/27 20:23:01 [debug] 28469#0: *3 connect to 127.0.0.1:11211, fd:14 #4
2011/09/27 20:23:01 [debug] 28469#0: *3 http upstream connect: -2
2011/09/27 20:23:01 [debug] 28469#0: *3 event timer add: 14:
100:1317126181141
2011/09/27 20:23:01 [debug] 28469#0: *3 http finalize request: -4,
"/memc?0123456789ABCDEF" a:1, c:3
2011/09/27 20:23:01 [debug] 28469#0: *3 http request count:3 blk:0
2011/09/27 20:23:01 [debug] 28469#0: *3 http run request:
"/memc?0123456789ABCDEF"
2011/09/27 20:23:01 [debug] 28469#0: *3 http upstream check client,
write event:1, "/memc"
2011/09/27 20:23:01 [debug] 28469#0: *3 http upstream recv(): -1 (11:
Resource temporarily unavailable)
2011/09/27 20:23:01 [debug] 28469#0: *3 http upstream request:
"/memc?0123456789ABCDEF" 1
2011/09/27 20:23:01 [debug] 28469#0: *3 http upstream send request handler
2011/09/27 20:23:01 [debug] 28469#0: *3 http upstream send request
2011/09/27 20:23:01 [debug] 28469#0: *3 chain writer buf fl:0 s:22
2011/09/27 20:23:01 [debug] 28469#0: *3 chain writer in: 0000000000786620
2011/09/27 20:23:01 [debug] 28469#0: *3 writev: 22
2011/09/27 20:23:01 [debug] 28469#0: *3 chain writer out: 0000000000000000
2011/09/27 20:23:01 [debug] 28469#0: *3 event timer del: 14: 1317126181141
2011/09/27 20:23:01 [debug] 28469#0: *3 event timer add: 14:
100:1317126181141
2011/09/27 20:23:01 [debug] 28469#0: *3 http upstream request:
"/memc?0123456789ABCDEF" 0
2011/09/27 20:23:01 [debug] 28469#0: *3 http upstream process header
2011/09/27 20:23:01 [debug] 28469#0: *3 malloc: 000000000077BDC0:4096
2011/09/27 20:23:01 [debug] 28469#0: *3 recv: fd:14 73 of 4096
2011/09/27 20:23:01 [debug] 28469#0: *3 memcached: "VALUE
0123456789ABCDEF 4 37"
2011/09/27 20:23:01 [debug] 28469#0: *3 srcache_fetch: subrequest
returned status 200
2011/09/27 20:23:01 [debug] 28469#0: *3 tcp_nodelay
2011/09/27 20:23:01 [debug] 28469#0: *3 memcached filter bytes:44
size:44 length:6 rest:7
2011/09/27 20:23:01 [error] 28469#0: *3 memcached sent invalid trailer
while reading response header from upstream, client: 127.0.0.1, server:
localhost, request: "GET /foo HTTP/1.1", subrequest: "/memc", upstream:
"memcached://127.0.0.1:11211", host: "localhost:9000"
2011/09/27 20:23:01 [debug] 28469#0: *3 http upstream process non
buffered downstream
2011/09/27 20:23:01 [debug] 28469#0: *3 http output filter
"/memc?0123456789ABCDEF"
2011/09/27 20:23:01 [debug] 28469#0: *3 http copy filter:
"/memc?0123456789ABCDEF"
2011/09/27 20:23:01 [emerg] 28469#0: *3 malloc(18446744073709551615)
failed (12: Cannot allocate memory) while sending to client, client:
127.0.0.1, server: localhost, request: "GET /foo HTTP/1.1", subrequest:
"/memc", upstream: "memcached://127.0.0.1:11211", host: "localhost:9000"
2011/09/27 20:23:01 [debug] 28469#0: *3 malloc:
0000000000000000:18446744073709551615