problem in writing handler module which should be called via ssi

Mauro Stettler mauro.stettler at gmail.com
Tue Jul 27 12:27:14 MSD 2010


found my problem with my module, it was simply because i've set the
last_buf to 1 in my buffer. now my problem seems solved.

still i'm wondering why the ssi is including those strange characters
into the outputted result...



On Tue, Jul 27, 2010 at 10:30, Mauro Stettler <mauro.stettler at gmail.com> wrote:
> 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