problem in writing handler module which should be called via ssi

Mauro Stettler mauro.stettler at gmail.com
Tue Jul 27 06:30:02 MSD 2010


i have to add that in the end of test.html and abc.html there was
actually a 0x0a and 0x0d, because they got added by my vi. but it
still doesn't explain those characters that i asked for in the
previous mail.


On Tue, Jul 27, 2010 at 10:28, Mauro Stettler <mauro.stettler at gmail.com> wrote:
> just now i discovered something strange, or maybe i just don't
> understand it. i did a very simple test of the nginx ssi module with
> the following nginx conf:
>
>  37         location / {
>  38             ssi on;
>  39             root   html;
>  40         }
>  41
>  42        location /gen_sec_link {
>  43             rewrite . /abc.html last;
>  45         }
>
> inside the html folder i have two files
>
> file test.html, no newlines or linebreaks:
>
> thisisatest <!--# include virtual="/gen_sec_link/this_is_my_link" -->
> some text abc <!--# include
> virtual="/gen_sec_link/this_is_another_link" -->
>
> file abc.html, no newlines or linebreaks:
>
> abc
>
>
> so if i request /test.html, as expected is the nginx doing two
> internal subrequests to /gen_sec_link and rewrites them to /abc.html.
> the content of /abc.html is the simple string "abc", so the two ssi
> tags will be replaced by "abc" and in the browser everything looks
> correct. but now i discovered that in the result that is sent to the
> browser there are some strange other characters somehow getting
> inbetween the replaced parts of the output and the original parts, but
> they are not shown in the browser so its not very obvious.
> this is what wireshark shows me as reply from nginx:
>
>    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 75 65 .7.67..D ate: Tue
>    00000030  2c 20 32 37 20 4a 75 6c  20 32 30 31 30 20 30 32 , 27 Jul  2010 02
>    00000040  3a 31 38 3a 31 36 20 47  4d 54 0d 0a 43 6f 6e 74 :18:16 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 63 0d 0a 74 68 p-alive. ...c..th
>    000000A0  69 73 69 73 61 74 65 73  74 20 0d 0a 34 0d 0a 61 isisates t ..4..a
>    000000B0  62 63 0a 0d 0a 66 0d 0a  20 73 6f 6d 65 20 74 65 bc...f..  some te
>    000000C0  78 74 20 61 62 63 20 0d  0a 34 0d 0a 61 62 63 0a xt abc . .4..abc.
>    000000D0  0d 0a 31 0d 0a 0a 0d 0a  30 0d 0a 0d 0a          ..1..... 0....
>
>
> so what is for example the byte number 13 on line 000000A0, why is
> there this 4? another example is the byte number 6 on line 000000B0,
> why is there an f?
>
> do i maybe understand something wrong or is that a problem of the ssi module?
>
>
>
> On Fri, Jul 23, 2010 at 15:13, Mauro Stettler <mauro.stettler at gmail.com> wrote:
>> thanks for the tip
>>
>> i did what you said and pushed the newest version of the code to
>> github. but i still haven't found the problem, it keeps behaving the
>> same way. in gdb the buffer which i am returning from my handler
>> function looks perfectly fine to me and its so simply that i can
>> hardly imagine that there is a problem:
>>
>>
>> Breakpoint 2, ngx_http_generate_secure_download_link_handler
>> (r=0x100860a18) at
>> src/http/modules/ngx_http_generate_secure_download_link//ngx_http_generate_secure_download_link.c:267
>> 267         return ngx_http_output_filter(r,&out);
>> (gdb) print *out->buf
>> $3 = {
>>  pos = 0x100861520
>> "/gen_sec_link/this_is_my_link/88bf88c2dfb3f5e71e4107711e749bea/4C49405B",
>>  last = 0x100861567 "",
>>  file_pos = 0,
>>  file_last = 0,
>>  start = 0x0,
>>  end = 0x0,
>>  tag = 0x0,
>>  file = 0x0,
>>  shadow = 0x0,
>>  temporary = 0,
>>  memory = 1,
>>  mmap = 0,
>>  recycled = 0,
>>  in_file = 0,
>>  flush = 0,
>>  sync = 0,
>>  last_buf = 1,
>>  last_in_chain = 0,
>>  last_shadow = 0,
>>  temp_file = 0,
>>  num = 0
>> }
>> (gdb) print out
>> $4 = {
>>  buf = 0x1008614d0,
>>  next = 0x0
>> }
>>
>>
>> looks like a perfectly fine buffer, no? or is there anything wrong
>> with that? i guess i will start debugging the ssi module to find out
>> what exactly is happening there.
>>
>> mauro
>>
>>
>>
>> On Thu, Jul 22, 2010 at 17:44, Weibin Yao <nbubingo at gmail.com> wrote:
>>> 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
>>>
>>>
>>> _______________________________________________
>>> nginx mailing list
>>> nginx at nginx.org
>>> http://nginx.org/mailman/listinfo/nginx
>>>
>>
>



More information about the nginx mailing list