problem in writing handler module which should be called via ssi
Weibin Yao
nbubingo at gmail.com
Thu Jul 22 13:44:22 MSD 2010
Mauro Stettler at 2010-7-22 16:06 wrote:
> thanks for the reply,
>
> i added the output of two requests to this mail. the first was working
> perfectly, the nginx gave the browser the result back and then closed
> the connection. in the second request the nginx also sent the result
> back to the browser but did then not close the connection... to me it
> seems like the problem happens if i refresh in very short time after i
> requested a page already, which does not really make any sense to me.
>
> i have noticed one more thing when i looked at the network traffic in
> wireshark. if i request a location with my module directly, which
> works perfectly, the output that comes from the nginx looks just as
> expected. but when i request a location with my module via ssi, there
> are some strange non-ascii characters in the output... is it possible
> that this is an ssi problem? that the ssi is maybe adding those
> strange characters when it operates on the buffer chain? in the end of
> the mail i also attached the output of the nginx in hex.
>
> good request ---------------------------------------------------------------------------------------
>
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http keepalive handler
> 2010/07/22 15:49:50 [debug] 22731#0: *2 malloc: 0000000100803A00:1024
> 2010/07/22 15:49:50 [debug] 22731#0: *2 recv: eof:0, avail:410, err:0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 recv: fd:7 410 of 1024
> 2010/07/22 15:49:50 [debug] 22731#0: *2 malloc: 0000000100810600:1248
> 2010/07/22 15:49:50 [debug] 22731#0: *2 malloc: 0000000100818200:4096
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http process request line
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http request line: "GET
> /test.html HTTP/1.1"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http uri: "/test.html"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http args: ""
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http exten: "html"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http process request header line
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http header: "Host: localhost:8080"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http header: "User-Agent:
> Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6; en-US; rv:1.9.2.7)
> Gecko/20100713 Firefox/3.6.7"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http header: "Accept:
> text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http header: "Accept-Language:
> en-us,en;q=0.5"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http header: "Accept-Encoding:
> gzip,deflate"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http header: "Accept-Charset:
> ISO-8859-1,utf-8;q=0.7,*;q=0.7"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http header: "Keep-Alive: 115"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http header: "Connection: keep-alive"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http header: "Cache-Control: max-age=0"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http header done
> 2010/07/22 15:49:50 [debug] 22731#0: *2 event timer del: 7: 1279785053298
> 2010/07/22 15:49:50 [debug] 22731#0: *2 generic phase: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 test location: "/"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 test location: "gen_sec_link"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 using configuration "/"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http cl:-1 max:1048576
> 2010/07/22 15:49:50 [debug] 22731#0: *2 generic phase: 2
> 2010/07/22 15:49:50 [debug] 22731#0: *2 post rewrite phase: 3
> 2010/07/22 15:49:50 [debug] 22731#0: *2 generic phase: 4
> 2010/07/22 15:49:50 [debug] 22731#0: *2 generic phase: 5
> 2010/07/22 15:49:50 [debug] 22731#0: *2 access phase: 6
> 2010/07/22 15:49:50 [debug] 22731#0: *2 access phase: 7
> 2010/07/22 15:49:50 [debug] 22731#0: *2 post access phase: 8
> 2010/07/22 15:49:50 [debug] 22731#0: *2 content phase: 9
> 2010/07/22 15:49:50 [debug] 22731#0: *2 content phase: 10
> 2010/07/22 15:49:50 [debug] 22731#0: *2 content phase: 11
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http filename:
> "/usr/local/nginx/0.7.67-gsdl/html/test.html"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 add cleanup: 0000000100818BF8
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http static fd: 8
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http set discard body
> 2010/07/22 15:49:50 [debug] 22731#0: *2 HTTP/1.1 200 OK
> Server: nginx/0.7.67
> Date: Thu, 22 Jul 2010 07:49:50 GMT
> Content-Type: text/html
> Transfer-Encoding: chunked
> Connection: keep-alive
>
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write new buf t:1 f:0
> 0000000100818F60, pos 0000000100818F60, size: 155 file: 0, size: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http write filter: l:0 f:0 s:155
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http output filter "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 copy filter: "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 read: 8, 00000001008190D0, 71, 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http ssi filter "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 saved: 0 state: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 malloc: 0000000100860A00:4096
> 2010/07/22 15:49:50 [debug] 22731#0: *2 parse: 0, looked: 0
> 00000001008190D0-00000001008190E0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 saved: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 ssi flush
> 2010/07/22 15:49:50 [debug] 22731#0: *2 ssi out: 0000000100819198
> 00000001008190D0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http postpone filter
> "/test.html?" 00000001008191E8
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http chunk: 16
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write old buf t:1 f:0
> 0000000100818F60, pos 0000000100818F60, size: 155 file: 0, size: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write new buf t:1 f:0
> 0000000000000000, pos 0000000100860B80, size: 4 file: 0, size: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write new buf t:1 f:0
> 00000001008190D0, pos 00000001008190D0, size: 16 file: 0, size: 71
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write new buf t:0 f:0
> 0000000000000000, pos 00000001000B3968, size: 2 file: 0, size: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http write filter: l:0 f:0 s:177
> 2010/07/22 15:49:50 [debug] 22731#0: *2 ssi include:
> "/gen_sec_link/this_is_my_link"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http subrequest
> "/gen_sec_link/this_is_my_link?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 copy filter: -2 "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http finalize request: -2,
> "/test.html?" 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 event timer add: 7: 60000:1279785050458
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http posted request:
> "/gen_sec_link/this_is_my_link?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 generic phase: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 test location: "/"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 test location: "gen_sec_link"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 using configuration "/gen_sec_link"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http cl:-1 max:1048576
> 2010/07/22 15:49:50 [debug] 22731#0: *2 generic phase: 2
> 2010/07/22 15:49:50 [debug] 22731#0: *2 post rewrite phase: 3
> 2010/07/22 15:49:50 [debug] 22731#0: *2 generic phase: 4
> 2010/07/22 15:49:50 [debug] 22731#0: *2 generic phase: 5
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http script var: "127.0.0.1"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http script var:
> "/gen_sec_link/this_is_my_link"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http output filter
> "/gen_sec_link/this_is_my_link?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 copy filter:
> "/gen_sec_link/this_is_my_link?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http postpone filter
> "/gen_sec_link/this_is_my_link?" 00007FFF5FBFEC10
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http chunk: 71
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write old buf t:1 f:0
> 0000000100818F60, pos 0000000100818F60, size: 155 file: 0, size: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write old buf t:1 f:0
> 0000000000000000, pos 0000000100860B80, size: 4 file: 0, size: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write old buf t:1 f:0
> 00000001008190D0, pos 00000001008190D0, size: 16 file: 0, size: 71
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write old buf t:0 f:0
> 0000000000000000, pos 00000001000B3968, size: 2 file: 0, size: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write new buf t:1 f:0
> 0000000000000000, pos 00000001008617A8, size: 4 file: 0, size: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write new buf t:0 f:0
> 0000000000000000, pos 0000000100861668, size: 71 file: 0, size: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write new buf t:0 f:0
> 0000000000000000, pos 00000001000B3960, size: 7 file: 0, size: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http write filter: l:1 f:0 s:259
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http write filter limit 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 writev: 259 of 259
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http write filter 0000000000000000
> 2010/07/22 15:49:50 [debug] 22731#0: *2 copy filter: 0
> "/gen_sec_link/this_is_my_link?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http finalize request: 0,
> "/gen_sec_link/this_is_my_link?" 1
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http wake parent request: "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http posted request: "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http writer handler: "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http output filter "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 copy filter: "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http ssi filter "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http ssi filter wait
> "/gen_sec_link/this_is_my_link?" done
> 2010/07/22 15:49:50 [debug] 22731#0: *2 saved: 0 state: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 parse: -2, looked: 0
> 0000000100819116-0000000100819117
> 2010/07/22 15:49:50 [debug] 22731#0: *2 saved: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 ssi out: 0000000100861850
> 0000000100819116
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http postpone filter
> "/test.html?" 0000000100861830
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http chunk: 1
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write new buf t:1 f:0
> 0000000000000000, pos 00000001008618F0, size: 3 file: 0, size: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write new buf t:1 f:0
> 00000001008190D0, pos 0000000100819116, size: 1 file: 0, size: 71
> 2010/07/22 15:49:50 [debug] 22731#0: *2 write new buf t:0 f:0
> 0000000000000000, pos 00000001000B3960, size: 7 file: 0, size: 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http write filter: l:1 f:0 s:11
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http write filter limit 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 writev: 11 of 11
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http write filter 0000000000000000
> 2010/07/22 15:49:50 [debug] 22731#0: *2 copy filter: 0 "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http writer output filter: 0,
> "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http writer done: "/test.html?"
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http finalize request: 0,
> "/test.html?" 1
> 2010/07/22 15:49:50 [debug] 22731#0: *2 event timer del: 7: 1279785050458
> 2010/07/22 15:49:50 [debug] 22731#0: *2 set http keepalive handler
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http close request
> 2010/07/22 15:49:50 [debug] 22731#0: *2 http log handler
> 2010/07/22 15:49:50 [debug] 22731#0: *2 malloc: 000000010081E200:4096
> 2010/07/22 15:49:50 [debug] 22731#0: *2 run cleanup: 0000000100818BF8
> 2010/07/22 15:49:50 [debug] 22731#0: *2 file cleanup: fd:8
> 2010/07/22 15:49:50 [debug] 22731#0: *2 free: 0000000100818200, unused: 8
> 2010/07/22 15:49:50 [debug] 22731#0: *2 free: 0000000100860A00, unused: 168
> 2010/07/22 15:49:50 [debug] 22731#0: *2 free: 000000010081E200, unused: 3868
> 2010/07/22 15:49:50 [debug] 22731#0: *2 event timer add: 7: 65000:1279785055458
> 2010/07/22 15:49:50 [debug] 22731#0: *2 free: 0000000100810600
> 2010/07/22 15:49:50 [debug] 22731#0: *2 free: 0000000100803A00
> 2010/07/22 15:49:50 [debug] 22731#0: *2 hc free: 0000000000000000 0
> 2010/07/22 15:49:50 [debug] 22731#0: *2 hc busy: 0000000000000000 0
>
>
>
> bad request ---------------------------------------------------------------------------------------
>
>
>
>
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http keepalive handler
> 2010/07/22 15:49:52 [debug] 22731#0: *2 malloc: 0000000100803A00:1024
> 2010/07/22 15:49:52 [debug] 22731#0: *2 recv: eof:0, avail:410, err:0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 recv: fd:7 410 of 1024
> 2010/07/22 15:49:52 [debug] 22731#0: *2 malloc: 0000000100810600:1248
> 2010/07/22 15:49:52 [debug] 22731#0: *2 malloc: 0000000100860A00:4096
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http process request line
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http request line: "GET
> /test.html HTTP/1.1"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http uri: "/test.html"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http args: ""
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http exten: "html"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http process request header line
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http header: "Host: localhost:8080"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http header: "User-Agent:
> Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6; en-US; rv:1.9.2.7)
> Gecko/20100713 Firefox/3.6.7"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http header: "Accept:
> text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http header: "Accept-Language:
> en-us,en;q=0.5"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http header: "Accept-Encoding:
> gzip,deflate"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http header: "Accept-Charset:
> ISO-8859-1,utf-8;q=0.7,*;q=0.7"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http header: "Keep-Alive: 115"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http header: "Connection: keep-alive"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http header: "Cache-Control: max-age=0"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http header done
> 2010/07/22 15:49:52 [debug] 22731#0: *2 event timer del: 7: 1279785055458
> 2010/07/22 15:49:52 [debug] 22731#0: *2 generic phase: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 test location: "/"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 test location: "gen_sec_link"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 using configuration "/"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http cl:-1 max:1048576
> 2010/07/22 15:49:52 [debug] 22731#0: *2 generic phase: 2
> 2010/07/22 15:49:52 [debug] 22731#0: *2 post rewrite phase: 3
> 2010/07/22 15:49:52 [debug] 22731#0: *2 generic phase: 4
> 2010/07/22 15:49:52 [debug] 22731#0: *2 generic phase: 5
> 2010/07/22 15:49:52 [debug] 22731#0: *2 access phase: 6
> 2010/07/22 15:49:52 [debug] 22731#0: *2 access phase: 7
> 2010/07/22 15:49:52 [debug] 22731#0: *2 post access phase: 8
> 2010/07/22 15:49:52 [debug] 22731#0: *2 content phase: 9
> 2010/07/22 15:49:52 [debug] 22731#0: *2 content phase: 10
> 2010/07/22 15:49:52 [debug] 22731#0: *2 content phase: 11
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http filename:
> "/usr/local/nginx/0.7.67-gsdl/html/test.html"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 add cleanup: 00000001008613F8
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http static fd: 8
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http set discard body
> 2010/07/22 15:49:52 [debug] 22731#0: *2 HTTP/1.1 200 OK
> Server: nginx/0.7.67
> Date: Thu, 22 Jul 2010 07:49:52 GMT
> Content-Type: text/html
> Transfer-Encoding: chunked
> Connection: keep-alive
>
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write new buf t:1 f:0
> 0000000100861760, pos 0000000100861760, size: 155 file: 0, size: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http write filter: l:0 f:0 s:155
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http output filter "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 copy filter: "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 read: 8, 00000001008618D0, 71, 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http ssi filter "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 saved: 0 state: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 malloc: 0000000100818200:4096
> 2010/07/22 15:49:52 [debug] 22731#0: *2 parse: 0, looked: 0
> 00000001008618D0-00000001008618E0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 saved: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 ssi flush
> 2010/07/22 15:49:52 [debug] 22731#0: *2 ssi out: 0000000100861998
> 00000001008618D0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http postpone filter
> "/test.html?" 00000001008619E8
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http chunk: 16
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write old buf t:1 f:0
> 0000000100861760, pos 0000000100861760, size: 155 file: 0, size: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write new buf t:1 f:0
> 0000000000000000, pos 0000000100818380, size: 4 file: 0, size: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write new buf t:1 f:0
> 00000001008618D0, pos 00000001008618D0, size: 16 file: 0, size: 71
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write new buf t:0 f:0
> 0000000000000000, pos 00000001000B3968, size: 2 file: 0, size: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http write filter: l:0 f:0 s:177
> 2010/07/22 15:49:52 [debug] 22731#0: *2 ssi include:
> "/gen_sec_link/this_is_my_link"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http subrequest
> "/gen_sec_link/this_is_my_link?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 copy filter: -2 "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http finalize request: -2,
> "/test.html?" 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 event timer add: 7: 60000:1279785052318
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http posted request:
> "/gen_sec_link/this_is_my_link?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 generic phase: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 test location: "/"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 test location: "gen_sec_link"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 using configuration "/gen_sec_link"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http cl:-1 max:1048576
> 2010/07/22 15:49:52 [debug] 22731#0: *2 generic phase: 2
> 2010/07/22 15:49:52 [debug] 22731#0: *2 post rewrite phase: 3
> 2010/07/22 15:49:52 [debug] 22731#0: *2 generic phase: 4
> 2010/07/22 15:49:52 [debug] 22731#0: *2 generic phase: 5
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http script var: "127.0.0.1"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http script var:
> "/gen_sec_link/this_is_my_link"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http output filter
> "/gen_sec_link/this_is_my_link?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 copy filter:
> "/gen_sec_link/this_is_my_link?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http postpone filter
> "/gen_sec_link/this_is_my_link?" 00007FFF5FBFEC10
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http chunk: 71
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write old buf t:1 f:0
> 0000000100861760, pos 0000000100861760, size: 155 file: 0, size: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write old buf t:1 f:0
> 0000000000000000, pos 0000000100818380, size: 4 file: 0, size: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write old buf t:1 f:0
> 00000001008618D0, pos 00000001008618D0, size: 16 file: 0, size: 71
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write old buf t:0 f:0
> 0000000000000000, pos 00000001000B3968, size: 2 file: 0, size: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write new buf t:1 f:0
> 0000000000000000, pos 0000000100818FA8, size: 4 file: 0, size: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write new buf t:0 f:0
> 0000000000000000, pos 0000000100818E68, size: 71 file: 0, size: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write new buf t:0 f:0
> 0000000000000000, pos 00000001000B3960, size: 7 file: 0, size: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http write filter: l:1 f:0 s:259
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http write filter limit 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 writev: 259 of 259
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http write filter 0000000000000000
> 2010/07/22 15:49:52 [debug] 22731#0: *2 copy filter: 0
> "/gen_sec_link/this_is_my_link?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http finalize request: 0,
> "/gen_sec_link/this_is_my_link?" 1
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http wake parent request: "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http posted request: "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http writer handler: "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http output filter "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 copy filter: "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http ssi filter "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http ssi filter wait
> "/gen_sec_link/this_is_my_link?" done
> 2010/07/22 15:49:52 [debug] 22731#0: *2 saved: 0 state: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 parse: -2, looked: 0
> 0000000100861916-0000000100861917
> 2010/07/22 15:49:52 [debug] 22731#0: *2 saved: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 ssi out: 0000000100819050
> 0000000100861916
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http postpone filter
> "/test.html?" 0000000100819030
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http chunk: 1
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write new buf t:1 f:0
> 0000000000000000, pos 00000001008190F0, size: 3 file: 0, size: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write new buf t:1 f:0
> 00000001008618D0, pos 0000000100861916, size: 1 file: 0, size: 71
> 2010/07/22 15:49:52 [debug] 22731#0: *2 write new buf t:0 f:0
> 0000000000000000, pos 00000001000B3960, size: 7 file: 0, size: 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http write filter: l:1 f:0 s:11
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http write filter limit 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 writev: 11 of 11
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http write filter 0000000000000000
> 2010/07/22 15:49:52 [debug] 22731#0: *2 copy filter: 0 "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http writer output filter: 0,
> "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http writer done: "/test.html?"
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http finalize request: 0,
> "/test.html?" 1
> 2010/07/22 15:49:52 [debug] 22731#0: *2 event timer del: 7: 1279785052318
> 2010/07/22 15:49:52 [debug] 22731#0: *2 set http keepalive handler
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http close request
> 2010/07/22 15:49:52 [debug] 22731#0: *2 http log handler
> 2010/07/22 15:49:52 [debug] 22731#0: *2 malloc: 000000010081E200:4096
> 2010/07/22 15:49:52 [debug] 22731#0: *2 run cleanup: 00000001008613F8
> 2010/07/22 15:49:52 [debug] 22731#0: *2 file cleanup: fd:8
> 2010/07/22 15:49:52 [debug] 22731#0: *2 free: 0000000100860A00, unused: 8
> 2010/07/22 15:49:52 [debug] 22731#0: *2 free: 0000000100818200, unused: 168
> 2010/07/22 15:49:52 [debug] 22731#0: *2 free: 000000010081E200, unused: 3868
> 2010/07/22 15:49:52 [debug] 22731#0: *2 event timer add: 7: 65000:1279785057318
> 2010/07/22 15:49:52 [debug] 22731#0: *2 free: 0000000100810600
> 2010/07/22 15:49:52 [debug] 22731#0: *2 free: 0000000100803A00
> 2010/07/22 15:49:52 [debug] 22731#0: *2 hc free: 0000000000000000 0
> 2010/07/22 15:49:52 [debug] 22731#0: *2 hc busy: 0000000000000000 0
>
>
> < pressing esc in browser after waiting around 20sec >
>
>
> 2010/07/22 15:49:57 [debug] 22731#0: *2 http keepalive handler
> 2010/07/22 15:49:57 [info] 22731#0: *2 kevent() reported that client
> 127.0.0.1 closed keepalive connection
> 2010/07/22 15:49:57 [debug] 22731#0: *2 close http connection: 7
> 2010/07/22 15:49:57 [debug] 22731#0: *2 event timer del: 7: 1279785057318
> 2010/07/22 15:49:57 [debug] 22731#0: *2 free: 0000000000000000
> 2010/07/22 15:49:57 [debug] 22731#0: *2 free: 0000000000000000
> 2010/07/22 15:49:57 [debug] 22731#0: *2 free: 00000001002002A0, unused: 8
> 2010/07/22 15:49:57 [debug] 22731#0: *2 free: 00000001002003A0, unused: 128
>
>
>
> hex output of request via ssi
> ---------------------------------------------------------------------------------------
>
> (for example the second and third byte on line 000000B0 are strange)
>
> 00000000 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d HTTP/1.1 200 OK.
> 00000010 0a 53 65 72 76 65 72 3a 20 6e 67 69 6e 78 2f 30 .Server: nginx/0
> 00000020 2e 37 2e 36 37 0d 0a 44 61 74 65 3a 20 54 68 75 .7.67..D ate: Thu
> 00000030 2c 20 32 32 20 4a 75 6c 20 32 30 31 30 20 30 37 , 22 Jul 2010 07
> 00000040 3a 31 32 3a 35 35 20 47 4d 54 0d 0a 43 6f 6e 74 :12:55 G MT..Cont
> 00000050 65 6e 74 2d 54 79 70 65 3a 20 74 65 78 74 2f 68 ent-Type : text/h
> 00000060 74 6d 6c 0d 0a 54 72 61 6e 73 66 65 72 2d 45 6e tml..Tra nsfer-En
> 00000070 63 6f 64 69 6e 67 3a 20 63 68 75 6e 6b 65 64 0d coding: chunked.
> 00000080 0a 43 6f 6e 6e 65 63 74 69 6f 6e 3a 20 6b 65 65 .Connect ion: kee
> 00000090 70 2d 61 6c 69 76 65 0d 0a 0d 0a 31 30 0d 0a 74 p-alive. ...10..t
> 000000A0 68 69 73 69 73 61 74 65 73 74 3c 62 72 3e 0a 0d hisisate st<br>..
> 000000B0 0a 34 37 0d 0a 2f 67 65 6e 5f 73 65 63 5f 6c 69 .47../ge n_sec_li
> 000000C0 6e 6b 2f 74 68 69 73 5f 69 73 5f 6d 79 5f 6c 69 nk/this_ is_my_li
> 000000D0 6e 6b 2f 33 31 38 32 64 32 61 38 36 31 39 36 35 nk/3182d 2a861965
> 000000E0 38 38 36 30 62 63 32 35 30 61 65 62 36 37 36 66 8860bc25 0aeb676f
> 000000F0 66 66 36 2f 34 43 34 37 45 46 37 37 0d 0a 30 0d ff6/4C47 EF77..0.
> 00000100 0a 0d 0a ...
> 00000103 31 0d 0a 0a 0d 0a 30 0d 0a 0d 0a 1.....0. ...
>
There must be some memory overlaps in your module.
I have read your source roughly. I suggest your use a local variable
instead of '&state->conf->secret' in the function of
ngx_http_script_run, and also the '&state->conf->url'.
This may be helpful.
--
Weibin Yao
More information about the nginx
mailing list