Possible bug with -f test

bkirkbri nginx-forum at nginx.us
Thu Jun 10 21:56:19 MSD 2010 

I'm seeing a problem with static file handling when using multiple -f tests in a location block.  I could be doing something stupid, but from the debug log it looks like a bug is corrupting the pathname nginx uses to serve the static file...

The corrupt filename should be "/tmp/home.html" but is in the debug log as:
[code]
2010/06/10 13:12:22 [debug] 15629#0: *3 http filename: "/tmp/home.htmlTP/1.1
Host"
[/code]

This is for nginx-0.7.66 compiled with: --with-http_realip_module --with-debug

Config:
[code]
    server {
        listen       174.37.76.178:80;
                listen            10.16.10.202:80;
        #listen       208.101.17.12:80;
        server_name  _;

                set $path_a             /var/www/otherpeoplespixels.com/sites/content;

                location ~ ^/(.+\.html)$ {
                        alias                   /tmp/$1;
                        expires                 1m;
                        log_not_found   off;
                        #error_page             404 = @catalyst;

                        set $is_down no;
                        if ( -f /tmp/$host/.down ) {
                                set $is_down yes;
                        }
                        if ( -f $path_a/$host/.grace_period ) {
                                set $is_down no;
                        }
                        if ( $is_down = yes ) {
                                return 503;
                        }
                }

    }

}
[/code]

Debug log:
[code]
2010/06/10 13:12:22 [debug] 15629#0: *3 accept: 192.168.0.100 fd:3
2010/06/10 13:12:22 [debug] 15629#0: *3 event timer add: 3: 60000:1276190002121
2010/06/10 13:12:22 [debug] 15629#0: *3 epoll add event: fd:3 op:1 ev:80000001
2010/06/10 13:12:22 [debug] 15629#0: timer delta: 7268
2010/06/10 13:12:22 [debug] 15629#0: posted events 0000000000000000
2010/06/10 13:12:22 [debug] 15629#0: worker cycle
2010/06/10 13:12:22 [debug] 15629#0: epoll timer: 60000
2010/06/10 13:12:22 [debug] 15629#0: epoll: fd:3 ev:0001 d:00007F476446C220
2010/06/10 13:12:22 [debug] 15629#0: *3 malloc: 00000000006A9FB0:1256
2010/06/10 13:12:22 [debug] 15629#0: *3 malloc: 000000000068DE30:256
2010/06/10 13:12:22 [debug] 15629#0: *3 malloc: 000000000069B180:1024
2010/06/10 13:12:22 [debug] 15629#0: *3 malloc: 000000000069B590:4096
2010/06/10 13:12:22 [debug] 15629#0: *3 http process request line
2010/06/10 13:12:22 [debug] 15629#0: *3 recv: fd:3 82 of 1024
2010/06/10 13:12:22 [debug] 15629#0: *3 http request line: "GET /home.html HTTP/1.1"
2010/06/10 13:12:22 [debug] 15629#0: *3 http uri: "/home.html"
2010/06/10 13:12:22 [debug] 15629#0: *3 http args: ""
2010/06/10 13:12:22 [debug] 15629#0: *3 http exten: "html"
2010/06/10 13:12:22 [debug] 15629#0: *3 http process request header line
2010/06/10 13:12:22 [debug] 15629#0: *3 http header: "Host: XXXXXXXXXXXXXXXX.com"
2010/06/10 13:12:22 [debug] 15629#0: *3 http header: "Connection: close"
2010/06/10 13:12:22 [debug] 15629#0: *3 http header done
2010/06/10 13:12:22 [debug] 15629#0: *3 event timer del: 3: 1276190002121
2010/06/10 13:12:22 [debug] 15629#0: *3 generic phase: 0
2010/06/10 13:12:22 [debug] 15629#0: *3 add cleanup: 000000000069BF50
2010/06/10 13:12:22 [debug] 15629#0: *3 generic phase: 1
2010/06/10 13:12:22 [debug] 15629#0: *3 http script value: "/usr/local/application/catalyst/root/sites"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script set $path_a
2010/06/10 13:12:22 [debug] 15629#0: *3 test location: ~ "^/(.+\.html)$"
2010/06/10 13:12:22 [debug] 15629#0: *3 using configuration "^/(.+\.html)$"
2010/06/10 13:12:22 [debug] 15629#0: *3 http cl:-1 max:1048576
2010/06/10 13:12:22 [debug] 15629#0: *3 generic phase: 3
2010/06/10 13:12:22 [debug] 15629#0: *3 http script value: "no"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script set $is_down
2010/06/10 13:12:22 [debug] 15629#0: *3 http script complex value
2010/06/10 13:12:22 [debug] 15629#0: *3 http script copy: "/tmp/"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script var: "XXXXXXXXXXXXXXXX.com"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script copy: "/.down"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script file op 0000000000000000 "/tmp/XXXXXXXXXXXXXXXX.com/.down"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script file op false
2010/06/10 13:12:22 [debug] 15629#0: *3 http script if
2010/06/10 13:12:22 [debug] 15629#0: *3 http script if: false
2010/06/10 13:12:22 [debug] 15629#0: *3 http script complex value
2010/06/10 13:12:22 [debug] 15629#0: *3 http script var: "/usr/local/application/catalyst/root/sites"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script copy: "/"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script var: "XXXXXXXXXXXXXXXX.com"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script copy: "/.grace_period"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script file op 0000000000000000 "/usr/local/application/catalyst/root/sites/XXXXXXXXXXXXXXXX.com/.grace_period"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script if
2010/06/10 13:12:22 [debug] 15629#0: *3 http script value: "no"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script set $is_down
2010/06/10 13:12:22 [debug] 15629#0: *3 http script var
2010/06/10 13:12:22 [debug] 15629#0: *3 http script var: "no"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script value: "yes"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script equal
2010/06/10 13:12:22 [debug] 15629#0: *3 http script equal: no
2010/06/10 13:12:22 [debug] 15629#0: *3 http script if
2010/06/10 13:12:22 [debug] 15629#0: *3 http script if: false
2010/06/10 13:12:22 [debug] 15629#0: *3 post rewrite phase: 4
2010/06/10 13:12:22 [debug] 15629#0: *3 generic phase: 5
2010/06/10 13:12:22 [debug] 15629#0: *3 add cleanup: 000000000069C270
2010/06/10 13:12:22 [debug] 15629#0: *3 generic phase: 6
2010/06/10 13:12:22 [debug] 15629#0: *3 generic phase: 7
2010/06/10 13:12:22 [debug] 15629#0: *3 access phase: 8
2010/06/10 13:12:22 [debug] 15629#0: *3 access phase: 9
2010/06/10 13:12:22 [debug] 15629#0: *3 post access phase: 10
2010/06/10 13:12:22 [debug] 15629#0: *3 content phase: 11
2010/06/10 13:12:22 [debug] 15629#0: *3 content phase: 12
2010/06/10 13:12:22 [debug] 15629#0: *3 content phase: 13
2010/06/10 13:12:22 [debug] 15629#0: *3 http script copy: "/tmp/"
2010/06/10 13:12:22 [debug] 15629#0: *3 http script capture: "home.html"
2010/06/10 13:12:22 [debug] 15629#0: *3 http filename: "/tmp/home.htmlTP/1.1
Host"
2010/06/10 13:12:22 [debug] 15629#0: *3 add cleanup: 000000000069C2B8
2010/06/10 13:12:22 [debug] 15629#0: *3 http finalize request: 404, "/home.html?" 1
2010/06/10 13:12:22 [debug] 15629#0: *3 http special response: 404, "/home.html?"
2010/06/10 13:12:22 [debug] 15629#0: *3 http set discard body
2010/06/10 13:12:22 [debug] 15629#0: *3 HTTP/1.1 404 Not Found
Server: nginx/0.7.66
Date: Thu, 10 Jun 2010 17:12:22 GMT
Content-Type: text/html
Content-Length: 169
Connection: close

2010/06/10 13:12:22 [debug] 15629#0: *3 write new buf t:1 f:0 000000000069C338, pos 000000000069C338, size: 150 file: 0, size: 0
2010/06/10 13:12:22 [debug] 15629#0: *3 http write filter: l:0 f:0 s:150
2010/06/10 13:12:22 [debug] 15629#0: *3 http output filter "/home.html?"
2010/06/10 13:12:22 [debug] 15629#0: *3 copy filter: "/home.html?"
2010/06/10 13:12:22 [debug] 15629#0: *3 http postpone filter "/home.html?" 000000000069C4F0
2010/06/10 13:12:22 [debug] 15629#0: *3 write old buf t:1 f:0 000000000069C338, pos 000000000069C338, size: 150 file: 0, size: 0
2010/06/10 13:12:22 [debug] 15629#0: *3 write new buf t:0 f:0 0000000000000000, pos 0000000000675D40, size: 116 file: 0, size: 0
2010/06/10 13:12:22 [debug] 15629#0: *3 write new buf t:0 f:0 0000000000000000, pos 00000000006757C0, size: 53 file: 0, size: 0
2010/06/10 13:12:22 [debug] 15629#0: *3 http write filter: l:1 f:0 s:319
2010/06/10 13:12:22 [debug] 15629#0: *3 http write filter limit 0
2010/06/10 13:12:22 [debug] 15629#0: *3 writev: 319
2010/06/10 13:12:22 [debug] 15629#0: *3 http write filter 0000000000000000
2010/06/10 13:12:22 [debug] 15629#0: *3 copy filter: 0 "/home.html?"
2010/06/10 13:12:22 [debug] 15629#0: *3 http finalize request: 0, "/home.html?" 1
2010/06/10 13:12:22 [debug] 15629#0: *3 http close request
2010/06/10 13:12:22 [debug] 15629#0: *3 http log handler
2010/06/10 13:12:22 [debug] 15629#0: *3 malloc: 0000000000692000:4096
2010/06/10 13:12:22 [debug] 15629#0: *3 free: 000000000069B590, unused: 96
2010/06/10 13:12:22 [debug] 15629#0: *3 free: 0000000000692000, unused: 3954
2010/06/10 13:12:22 [debug] 15629#0: *3 close http connection: 3
2010/06/10 13:12:22 [debug] 15629#0: *3 free: 000000000069B180
2010/06/10 13:12:22 [debug] 15629#0: *3 free: 00000000006A9FB0
2010/06/10 13:12:22 [debug] 15629#0: *3 free: 000000000068DB50, unused: 8
2010/06/10 13:12:22 [debug] 15629#0: *3 free: 000000000068DE30, unused: 128
2010/06/10 13:12:22 [debug] 15629#0: timer delta: 0
2010/06/10 13:12:22 [debug] 15629#0: posted events 0000000000000000
2010/06/10 13:12:22 [debug] 15629#0: worker cycle
2010/06/10 13:12:22 [debug] 15629#0: epoll timer: -1
[/code]

This occurs for all possible combinations of true/false results for the two -f tests.
The existence of /tmp/$host/.down has no effect.
BUT, if the directory $path_a/$host does NOT exist, this corruption does NOT happen.

I am happy to try permutations of this config and or request as needed to help track down the cause.

Best,
Brian

Posted at Nginx Forum: http://forum.nginx.org/read.php?2,96823,96823#msg-96823

More information about the nginx mailing list