Problem in writing handler module which should be called via ssi

Mauro_Stettler · July 21, 2010, 10:24am

hi

i have a problem while writing an nginx module which i want to
generate secure download links, which can then be verified by the
NginxHttpSecureDownload module and later maybe also the secure link
module. i wrote it as a content handler which can then be called over
an ssi include, like in the following example:

<a href=“”>my
link

together with the nginx conf:

    location / {
        ssi on;
        root   html;
    }

   location /gen_sec_link {
        generate_secure_download_link_expiration_time 3600;
        generate_secure_download_link_secret $remote_addr;
        generate_secure_download_link_url $uri;
        generate_secure_download_link;
    }

the result will be something like:

my
link

by using SSI i can save all the pattern matching and operating on the
buffer chain, thats why i did it as handler module, instead of an
output filter.

i pushed the code to github:

now my problem is that sometimes when i request many times from one
browser it just never closes the connection and the browser seems to
keep loading. first i thought the problem might be a mistake in the
calculation of the content-length, but after many tests i believe that
the content length that i give back is correct. i’m guessing that i
missed something to tell nginx that the content is really finished
now. on the other hand its strange that i only have this problem after
refreshing a page which i requested already, the first request is
always working.

i would be glad for a few tips what else i have to check,

thanks,

mauro

Mauro_Stettler · July 22, 2010, 8:11am

i have also realized that this problem really only happens if i access
the location which has the generate_secure_download_link enabled via
ssi. if i directly request a uri in the location with the module
enabled i don’t have any problem at all, only if the location gets
called via the virtual of the ssi, i run into this problem that
sometimes nginx doesn’t close the connection to the client right.

would there maybe be any better way to implement what i am trying to
achieve? do i really have to do search and replace on the output
buffer chain?

Mauro_Stettler · July 22, 2010, 9:38am

Mauro Stettler at 2010-7-22 14:10 wrote:

What does the debug.log show?

<a href=“”>my link
generate_secure_download_link_expiration_time 3600;
by using SSI i can save all the pattern matching and operating on the
calculation of the content-length, but after many tests i believe that
mauro

nginx mailing list
[email protected]
nginx Info Page

–
Weibin Y.

Mauro_Stettler · July 22, 2010, 11:45am

Mauro Stettler at 2010-7-22 16:06 wrote:

wireshark. if i request a location with my module directly, which
2010/07/22 15:49:50 [debug] 22731#0: *2 malloc: 0000000100803A00:1024
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: "Accept-Charset:
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 http filename:

00000001008190D0-00000001008190E0
0000000000000000, pos 0000000100860B80, size: 4 file: 0, size: 0
2010/07/22 15:49:50 [debug] 22731#0: *2 http finalize request: -2,
2010/07/22 15:49:50 [debug] 22731#0: *2 post rewrite phase: 3
“/gen_sec_link/this_is_my_link?” 00007FFF5FBFEC10
0000000000000000, pos 00000001008617A8, size: 4 file: 0, size: 0
2010/07/22 15:49:50 [debug] 22731#0: *2 http finalize request: 0,
2010/07/22 15:49:50 [debug] 22731#0: *2 parse: -2, looked: 0
00000001008190D0, pos 0000000100819116, size: 1 file: 0, size: 71
2010/07/22 15:49:50 [debug] 22731#0: *2 http finalize request: 0,
2010/07/22 15:49:50 [debug] 22731#0: *2 free: 000000010081E200, unused: 3868

/test.html HTTP/1.1"
2010/07/22 15:49:52 [debug] 22731#0: *2 http header: "Accept-Language:
2010/07/22 15:49:52 [debug] 22731#0: *2 generic phase: 0
2010/07/22 15:49:52 [debug] 22731#0: *2 post access phase: 8
Date: Thu, 22 Jul 2010 07:49:52 GMT
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 chunk: 16
“/gen_sec_link/this_is_my_link”
2010/07/22 15:49:52 [debug] 22731#0: *2 test location: “gen_sec_link”
“/gen_sec_link/this_is_my_link?”
00000001008618D0, pos 00000001008618D0, size: 16 file: 0, size: 71
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 ssi filter “/test.html?”
2010/07/22 15:49:52 [debug] 22731#0: *2 http chunk: 1
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 run cleanup: 00000001008613F8

2010/07/22 15:49:57 [debug] 22731#0: *2 free: 00000001002002A0, unused: 8
00000010 0a 53 65 72 76 65 72 3a 20 6e 67 69 6e 78 2f 30 .Server: nginx/0
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 Y.

Mauro_Stettler · July 22, 2010, 10:07am

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
…
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.
…

Mauro_Stettler · July 27, 2010, 4:29am

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
some text abc

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?

Mauro_Stettler · July 27, 2010, 4:31am

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.

Mauro_Stettler · July 23, 2010, 9:15am

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

Mauro_Stettler · July 27, 2010, 10:28am

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…